Concurrency key proc is missing arguments when retrying a discarded job.

[zarqman]

Summary

good_job fails to populate arguments when asked to retry a previously discarded job. This presents a problem when using a dynamic concurrency key, which can cause an error inside the :key Proc due to the missing arguments. Specifically, arguments is showing up as an empty array.

In my particular case, arguments contains a globalid reference, but a job with only scalar arguments shows the same problem.

Background

I have a job that was erroring so I discarded it. Later, I went back to the UI and selected Retry job.

The job in question has arguments of:

"arguments": [
  {
    "_aj_globalid": "gid://my-app/TheModel/12345678"
  }
]

The job class has a concurrency key that relies on that globalid:

good_job_control_concurrency_with(
  perform_limit: 1,
  key: ->{
    puts "[CONCURRENCY KEY] arguments = #{arguments.inspect}"
    obj = arguments.first
    "workerjob-#{obj.id}"
  }
)

Under normal circumstances, arguments is correctly populated with [obj] (or whatever else). But, it's an empty array when good_job attempts to enqueue the job for the requested retry:

Started PUT "/goodjob/jobs/3c18fdd5-0ac7-4103-b9a4-1b5f56e64351/retry" for 127.0.0.1 at 2022-02-05 13:51:46 -0700
Processing by GoodJob::JobsController#retry as HTML
  Parameters: {"authenticity_token"=>"[FILTERED]", "id"=>"3c18fdd5-0ac7-4103-b9a4-1b5f56e64351"}
  GoodJob::ActiveJobJob Load (0.6ms)  SELECT "good_jobs".* FROM "good_jobs" WHERE "good_jobs"."retried_good_job_id" IS NULL AND "good_jobs"."active_job_id" = $1 LIMIT $2  [["active_job_id", "3c18fdd5-0ac7-4103-b9a4-1b5f56e64351"], ["LIMIT", 1]]
  GoodJob::Lockable Advisory Lock (0.2ms)  SELECT pg_try_advisory_lock(('x'||substr(md5($1::text), 1, 16))::bit(64)::bigint) AS locked  [["key", "good_jobs-3c18fdd5-0ac7-4103-b9a4-1b5f56e64351"]]
  GoodJob::Execution Load (0.3ms)  SELECT "good_jobs".* FROM "good_jobs" WHERE "good_jobs"."active_job_id" = $1 ORDER BY "good_jobs"."created_at" ASC  [["active_job_id", "3c18fdd5-0ac7-4103-b9a4-1b5f56e64351"]]
[CONCURRENCY KEY] arguments = []     <-- my added logging from inside the :key Proc above
[ActiveJob] Failed enqueuing WorkerJob to GoodJob(default): NoMethodError (undefined method `id' for nil:NilClass)
Retrying WorkerJob in 0 seconds, due to a String.
  GoodJob::Lockable Advisory Unlock (0.3ms)  SELECT pg_advisory_unlock(('x'||substr(md5($1::text), 1, 16))::bit(64)::bigint) AS unlocked  [["key", "good_jobs-3c18fdd5-0ac7-4103-b9a4-1b5f56e64351"]]
Completed 500 Internal Server Error in 10ms (ActiveRecord: 1.4ms | Allocations: 4344)

Using web-console from the retry attempt shows that @serialized_arguments still has the arguments. And, if the concurrency :key Proc is bypassed, the jobs do schedule and execute with the original arguments.

Also, rescheduling an errored job that's still eligible for a reattempt seems to work fine (although it didn't seem to check the concurrency key in this case--presumably because it's already enqueued?). It appears the issue is limited to retrying discarded jobs.

Is it possible that the discarded->retry operation isn't properly parsing/preparing arguments in advance of enqueuing the job?

Environment

good_job 2.9.4
rails 7.0.1

[bensheldon]

@zarqman thank you for the comprehensive bug report! I took a quick initial look and I think I have an explanation and possible fix.

ActiveJob's retry behavior doesn't expect to be triggered from outside the context of job execution. GoodJob tries to set it up, but it looks like I did that insufficiently. There is a private ActiveJob method called deserialize_arguments_if_needed; I'm hypothesizing that if GoodJob invokes that in its own retry code, it will correctly populate arguments.

I think this line should be something like this, instead:

def active_job
  ActiveJob::Base.deserialize(active_job_data).tap do |aj|
    aj.send(:deserialize_arguments_if_needed)
  end
end

I can make a PR for that and test it unless you're able to get to it first.

[bensheldon]

@zarqman Fix is released inv2.9.5.

[zarqman]

Thank you for your super quick fix! 👍