ActiveJob job is enqueued but then disappears from logs

Question

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?

• Rails version: 5.8.2.1
• Resque version: 2.4.0

Answer 1

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.