We have thousands of jobs being processed by Resque but twice now a specific job is enqueued but never performed.
In the activejob log I can see it is enqueued:
[ActiveJob] Enqueued SendMarketJob (Job ID: c37f2098-9f7b-4b73-a7f0-b6b44e057535) to Resque(console_high) with arguments: #<GlobalID:0x00007f19f34a1848 @uri=#<URI::GID gid://console/Market/57141>>
But after that it disappears.
Normally I would see something like the following:
[ActiveJob] [SendMarketJob] Performing SendMarketJob (Job ID: c37f2098-9f7b-4b73-a7f0-b6b44e057535) from Resque(console_high) with arguments: #<GlobalID:0x000000000767cd50 @uri=#<URI::GID gid://console/Market/57141>
[ActiveJob] [SendMarketJob] Performed SendMarketJob (Job ID: c37f2098-9f7b-4b73-a7f0-b6b44e057535) from Resque(console_high) in 4878.01ms
Any thoughts on how this could happen?
And is there any logging I can add to see why it happens, if it happens again?
According to this issue on GitHub this version of ActiveJob can say that a job is enqueued when it actually isn't. I think this is the most likely scenario.
From the linked issue:
Fix ActiveJob logging when callback chain is halted:
Problem:
ActiveJob will always log "Enqueued MyJob (Job ID) ..." even if the job doesn't get enqueued through the adapter. Same problem happens when performing a Job, "Performed MyJob (Job ID) ..." will be logged even when job wasn't performed at all. This situation can happen either if the callback chain is terminated (before_enqueue throwing an abort) or if an exception is raised.
Solution:
Check if the callback chain is aborted/exception is raised, and log accordingly.