Rails 5.1 ActiveJob on Puma development not performing specific enqueued job

Question

I'm running Rails 5.1.4 server (Puma v. 3.10.0 in single mode), but having an issue with a specific ActionJob that get's enqueued correctly but often never performed.

I have a handful of jobs. All but 1 specific job always gets performed asynchronously like expected shortly after enqueuing them.

First time after a server restart my specific job gets performed correctly after a new queueing. But after the first successful run, it will not get performed on following enqueuings.

I'm queueing all jobs generally with perform_later.

I've tested queuing the specific job using rails console as well. Whenever I queue it in the console, it gets performed instantly. Even in same session. Also tried with same arguments as used in the application when it's getting queued in the rails server, but in server it only gets queued. Never performed.

I've checked the log files - there is nothing, no errors, no fatals, no warnings. It simply states [ActiveJob] Enqueued FooBaaJob, but never performs the job.

If the job actually failed, it should at least still get to write out [ActiveJob] [FooBaaJob] [id] Performing FooBaaJob in the log, but it doesn't. And per https://github.com/rails/rails/blob/master/activejob/lib/active_job/logging.rb#L78 it should actually catch and log the exception if it was failing. Secondly it never fails to run in console, so that shouldn't be the case.

Any ideas about where to look?

Answer 1

Okay, so I finally found a way to debug this issue.

By creating an initializer file in config/initializers with this line: Concurrent.use_stdlib_logger(Logger::DEBUG)

I now get error data output to my console.

[ActiveJob] Enqueued FooBaaJob (Job ID: ...) to Async(default) with arguments: #<GlobalID:0...0 @uri=#<URI::GID gid://test-app/FooBaa/8>>
[2017-10-29 16:10:56.676] DEBUG -- : Error while trying to deserialize arguments: Couldn't find FooBaa with 'id'=8 (ActiveJob::DeserializationError)

The second line is the result of adding the Concurrent.use_stdlib_logger(Logger::DEBUG) initiator file.

In my case I'm initiating the job in an after_create in my model and I'm guessing the job executions happens instantaneously in a manner, that results in the record not fully being committed to the sqlite db yet when ActiveJob is trying to load it. It did test this on MySQL as well, same result.

Rails 5.0 introduced after_[create|update|destroy]_commit, so changing my after_create to after_create_commit fixed my issue and the job is now running as expected each time I'm trying.

For earlier versions of Rails you could have moved to after_commit with an on: :create argument or similar.