Skip to content

Log when SidekiqStatus is used unexpectedly

Sean McGivern requested to merge log-unexpected-sidekiq-status-users into master

We want to make SidekiqStatus purely opt-in. All known users now set a status_expiration field on the job, either through the sidekiq_options on the worker class, or using Worker.with_status.perform_async.

However, before we start only tracking job statuses for these known cases, we want to verify that we are not missing any cases. This commit:

  1. Makes the client middleware set a different value in Redis when the job has opted in (2 instead of 1).
  2. Changes the status checking method to log when it finds the default value (1), indicating that the job was checked but not opted in.

Because item 2 can only work when the job is enqueued or running, it's possible we would miss some edge cases that only check job status after the job finishes. This should be smoothed out across all runs of the various workers, though: if a worker runs so fast that all of its status checks show that it is done, then we probably don't need to worry too much about checking its status anyway!

This is behind the feature flag log_implicit_sidekiq_status_calls, which is disabled by default. It should be safe to use a feature flag here as SidekiqStatus isn't read by middleware, only set - it's read by models and workers, and the model methods will also be called from HTTP endpoints or workers.

Testing

This shouldn't log anything in normal use. We can apply the below patch to make merges log:

diff --git a/app/models/merge_request.rb b/app/models/merge_request.rb
index 8bc4a9db20a..5d18c40b9c6 100644
--- a/app/models/merge_request.rb
+++ b/app/models/merge_request.rb
@@ -662,7 +662,7 @@ def supports_suggestion?
   # updates `merge_jid` with the MergeWorker#jid.
   # This helps tracking enqueued and ongoing merge jobs.
   def merge_async(user_id, params)
-    jid = MergeWorker.with_status.perform_async(id, user_id, params.to_h)
+    jid = MergeWorker.perform_async(id, user_id, params.to_h)
     update_column(:merge_jid, jid)
 
     # merge_ongoing? depends on merge_jid
diff --git a/app/workers/merge_worker.rb b/app/workers/merge_worker.rb
index 3fcd7a3ad7a..08932fb9ff2 100644
--- a/app/workers/merge_worker.rb
+++ b/app/workers/merge_worker.rb
@@ -25,6 +25,8 @@ def perform(merge_request_id, current_user_id, params)
       return
     end
 
+    sleep 120
+
     MergeRequests::MergeService.new(project: merge_request.target_project, current_user: current_user, params: params)
       .execute(merge_request)
   end

Next:

  1. Create a merge request.

  2. Merge it.

  3. While it's merging (the sleep 120) refresh the page, or do MergeRequest.last.merge_ongoing?.

  4. You'll see something like this in log/sidekiq_client.log:

    {"severity":"INFO","time":"2021-11-25T14:07:42.858Z","message":"Keys using the default value for SidekiqStatus detected","keys":["gitlab-sidekiq-status:0aff881a38675750d4453be1"],"retry":0}

For #343964 (closed).

Edited by Sean McGivern

Merge request reports