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?

Radiothorium

What do you have your job queue set to for your development environment? – Kisner

async (default - not set explicitly) and all jobs in default queue. Whenever I try to run the job queue inline it always executes the job successfully. – Radiothorium

And you're passing a configuration to Puma only allowing one thread? This is maybe your problem, as async will spawn a new Thread? – Kisner

I'm not sure why it's single threaded as I'm just using rails server command with no additional Puma config than default. However all my other jobs runs as expected, it's only this one specific job that fails. – Radiothorium

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.

Radiothorium

Thanks, I had exactly the same cause of this issue: used afrer_create callback for starting job. However, the debugging solution using Concurrent.use_stdlib_logger(Logger::DEBUG) seems to be outdated: at least my IDE complains that Concurrent.use_stdlib_logger call is deprecated. – Berwick