Skip to content

Log Sidekiq job_status as deferred for deferred jobs

Gregorius Marco requested to merge mg-defer-jobs-logging into master

What does this MR do and why?

Currently, the shape of the logs for deferred jobs is:

{"job_status": "start", ...}
{"message": "Deferring ...}
{"job_status": "done", ...}

This is confusing as the job_status: done does not actually mean the job is done, because it was deferred in DeferJobs Sidekiq server middleware.

The resulting log will look like:

{"job_status": "start", ...}
{"job_status": "deferred", ...}

Resolves gitlab-com/gl-infra/scalability#2368 (closed)

How to set up and validate locally

  1. Enable the feature flag to defer the job Feature.enable(:"defer_sidekiq_jobs_Chaos::SleepWorker")
  2. Run a job with Chaos::SleepWorker.perform_async(1)
  3. Check Sidekiq log from gdk tail rails-background-jobs
2023-05-23_08:35:42.28200 rails-background-jobs : {"severity":"INFO","time":"2023-05-23T08:35:42.277Z","retry":3,"queue":"default","backtrace":true,"version":0,"queue_namespace":"chaos","args":["1"],"class":"Chaos::SleepWorker","jid":"58faa80a0796f77280440f57","created_at":"2023-05-23T08:35:42.185Z","correlation_id":"1474c5d60a54c9025cd8f79fd13935d8","worker_data_consistency":"always","idempotency_key":"resque:gitlab:duplicate:default:2f0bc834677c58fe9b274ea1acbbcd384d61ad88243f7ae8b6c38429900bba4f","duplicate-of":"dca290c18af17d439a490475","size_limiter":"validated","enqueued_at":"2023-05-23T08:35:42.275Z","job_size_bytes":3,"pid":85505,"message":"Chaos::SleepWorker JID-58faa80a0796f77280440f57: start","job_status":"start","scheduling_latency_s":0.002243}
2023-05-23_08:35:42.32147 rails-background-jobs : {"severity":"INFO","time":"2023-05-23T08:35:42.321Z","retry":3,"queue":"default","backtrace":true,"version":0,"queue_namespace":"chaos","args":["1"],"class":"Chaos::SleepWorker","jid":"58faa80a0796f77280440f57","created_at":"2023-05-23T08:35:42.185Z","correlation_id":"1474c5d60a54c9025cd8f79fd13935d8","worker_data_consistency":"always","idempotency_key":"resque:gitlab:duplicate:default:2f0bc834677c58fe9b274ea1acbbcd384d61ad88243f7ae8b6c38429900bba4f","duplicate-of":"dca290c18af17d439a490475","size_limiter":"validated","enqueued_at":"2023-05-23T08:35:42.275Z","job_size_bytes":3,"pid":85505,"message":"Chaos::SleepWorker JID-58faa80a0796f77280440f57: deferred: 0.043792 sec","job_status":"deferred","scheduling_latency_s":0.002243,"redis_calls":5,"redis_duration_s":0.0012690000000000002,"redis_read_bytes":5,"redis_write_bytes":1051,"redis_feature_flag_calls":2,"redis_feature_flag_duration_s":0.000746,"redis_feature_flag_read_bytes":2,"redis_feature_flag_write_bytes":367,"redis_queues_calls":3,"redis_queues_duration_s":0.000523,"redis_queues_read_bytes":3,"redis_queues_write_bytes":684,"db_count":1,"db_write_count":0,"db_cached_count":0,"db_replica_count":0,"db_primary_count":1,"db_main_count":1,"db_ci_count":0,"db_main_replica_count":0,"db_ci_replica_count":0,"db_replica_cached_count":0,"db_primary_cached_count":0,"db_main_cached_count":0,"db_ci_cached_count":0,"db_main_replica_cached_count":0,"db_ci_replica_cached_count":0,"db_replica_wal_count":0,"db_primary_wal_count":0,"db_main_wal_count":0,"db_ci_wal_count":0,"db_main_replica_wal_count":0,"db_ci_replica_wal_count":0,"db_replica_wal_cached_count":0,"db_primary_wal_cached_count":0,"db_main_wal_cached_count":0,"db_ci_wal_cached_count":0,"db_main_replica_wal_cached_count":0,"db_ci_replica_wal_cached_count":0,"db_replica_duration_s":0.0,"db_primary_duration_s":0.002,"db_main_duration_s":0.002,"db_ci_duration_s":0.0,"db_main_replica_duration_s":0.0,"db_ci_replica_duration_s":0.0,"cpu_s":0.018059,"worker_id":"sidekiq_0","rate_limiting_gates":[],"duration_s":0.043792,"completed_at":"2023-05-23T08:35:42.321Z","load_balancing_strategy":"primary","db_duration_s":0.014926}

Numbered steps to set up and validate the change are strongly suggested.

MR acceptance checklist

This checklist encourages us to confirm any changes have been analyzed to reduce risks in quality, performance, reliability, security, and maintainability.

Edited by Gregorius Marco

Merge request reports

Loading