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 (closed)
How to set up and validate locally
- Enable the feature flag to defer the job
Feature.enable(:"defer_sidekiq_jobs_Chaos::SleepWorker")
- Run a job with
Chaos::SleepWorker.perform_async(1)
- 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.
-
I have evaluated the MR acceptance checklist for this MR.
Edited by Gregorius Marco