Skip to content

Log Sidekiq job_status as deferred for deferred jobs

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

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 Marco Gregorius

Merge request reports

Loading