Jobs Hanging/Delayed in Rails Console

[ankane]

Steps to reproduce

(sorry, only happens with Rails console, so couldn't create a script)

Create a job:

class TestJob < ApplicationJob
  def perform
    puts "Job enqueued for #{Time.now - Time.parse(enqueued_at)} seconds"
  end
end

Create a user that runs the job in a callback:

class User < ApplicationRecord
  before_save :run_job

  def run_job
    TestJob.perform_later
  end
end

Run rails console and before running any other jobs, run:

User.create!

Expected behavior

The job should run immediately, like it does if you run:

TestJob.perform_later

or

TestJob.perform_later; User.create!

Actual behavior

If you use a Postgres database, the job will hang indefinitely (until you press control + c twice on Mac). If you use SQLite, the job will be delayed for 10 seconds. This only happens with the default async adapter, not the inline adapter. Jobs seem to hang at other points as well (was originally going to post on A May of WTFs), but can only reliably reproduce if it's the first job run.

Enqueued TestJob (Job ID: 876b2347-0280-4e80-8309-eef3f1e08a4a) to Async(default)
Performing TestJob (Job ID: 876b2347-0280-4e80-8309-eef3f1e08a4a) from Async(default) enqueued at 2020-05-25T23:59:39Z
Job enqueued for 10.330646 seconds
Performed TestJob (Job ID: 876b2347-0280-4e80-8309-eef3f1e08a4a) from Async(default) in 5.41ms

If you use after_save or after_commit (like ActiveStorage::PurgeJob and ActiveStorage::AnalyzeJob), jobs are delayed for 10 seconds as well.

This seems like a weird one, so I'm not sure if it's just my machine or others are seeing this as well.

System configuration

Rails version: 6.0.3.1

Ruby version: 2.7.1

[jonathanhefner]

Unfortunately, I couldn't reproduce the issue (using Rails 6.0.3.1 and Ruby 2.7.0):

Enqueued TestJob (Job ID: abd53e7a-cc7d-4044-8171-fc97c29145d2) to Async(default)
Performing TestJob (Job ID: abd53e7a-cc7d-4044-8171-fc97c29145d2) from Async(default) enqueued at 2020-05-26T04:59:23Z
Job enqueued for 0.743927856 seconds
Performed TestJob (Job ID: abd53e7a-cc7d-4044-8171-fc97c29145d2) from Async(default) in 71.9ms

This does seem like a weird one... Does tweaking the concurrency level affect anything? e.g.:

config.active_job.queue_adapter = ActiveJob::QueueAdapters::AsyncAdapter.new(min_threads: 1, max_threads: 1)

[ankane]

Hey @jonathanhefner, thanks for the response! Unfortunately, trying different min_threads/max_threads didn't fix it. Here's what the output looks like when it hangs.

Enqueued TestJob (Job ID: 0194cc20-97f3-44a6-9436-44ec56be5630) to Async(default)
   (0.2ms)  BEGIN
  User Create (0.9ms)  INSERT INTO "users" ("created_at", "updated_at") VALUES ($1, $2) RETURNING "id"  [["created_at", "2020-05-26 19:01:15.439583"], ["updated_at", "2020-05-26 19:01:15.439583"]]
^C   (20278.2ms)  COMMIT
WARNING:  there is no transaction in progress
^C   (7125.6ms)  ROLLBACK
Traceback (most recent call last):
        1: from (irb):1
IRB::Abort (abort then interrupt!)
irb(main):002:0> Performing TestJob (Job ID: 0194cc20-97f3-44a6-9436-44ec56be5630) from Async(default) enqueued at 2020-05-26T19:01:15Z
Job enqueued for 27.908165 seconds
Performed TestJob (Job ID: 0194cc20-97f3-44a6-9436-44ec56be5630) from Async(default) in 6.1ms

Either the INSERT or COMMIT will hang until control + c and the job won't run until after a 2nd control + c.

I'm on Mac 10.14 fwiw. On further investigation, looks like it's only happening with Spring.

[jonathanhefner]

On further investigation, looks like it's only happening with Spring.

Ahah! Activating Spring allowed me to reproduce the issue. Here's what's happening:

1. spring rails console starts the console in a different process than the one Rails was originally loaded in.

2. Rails.application.reloaders.map(&:updated?).any? is true because Process.pid is different.

3. Post.create! establishes a database connection which is owned by the console thread.

4. The AsyncAdapter worker thread triggers :execute callbacks, which calls reloader.wrap, which calls reloader.run! (which proceeds because reloaders.map(&:updated?).any? is true), which triggers :run callbacks, which triggers :class_unload callbacks.

5. :class_unload callbacks trigger ActiveRecord::Base.clear_reloadable_connections!.

6. clear_reloadable_connections times out after 10 seconds because it can't checkout the database connection that is owned by the console thread.

So it turns out the issue can also be reproduced without Spring:

# Establish db connection
ActiveRecord::Base.connection; nil

# Reload app from different thread
Thread.new do
  t = Time.now
  Rails.application.reloader.reload!
  puts "#{Time.now - t} seconds"
end

But that reproduction seems like an edge case we may not care about. However, it does seem like there should be better integration / coordination / awareness between EventedFileUpdateChecker and Spring.

[ankane]

Wow, nice debugging!! The code reproduces it for me as well. This sounds like a difficult one. I imagine something like eager reloading after the fork isn't ideal.

[georgeclaghorn]

We’ve been seeing this with MySQL, too.

[rails-bot]

This issue has been automatically marked as stale because it has not been commented on for at least three months.
The resources of the Rails team are limited, and so we are asking for your help.
If you can still reproduce this error on the 6-0-stable branch or on master, please reply with all of the information you have about it in order to keep the issue open.
Thank you for all your contributions.