Log when SidekiqStatus is used unexpectedly
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:
- Makes the client middleware set a different value in Redis when the job has opted in (2 instead of 1).
- 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:
-
Create a merge request.
-
Merge it.
-
While it's merging (the
sleep 120
) refresh the page, or doMergeRequest.last.merge_ongoing?
. -
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).