Workers eventually stop working

[carsoncole]

I seem to have a persistent problem of jobs being worked but new jobs just get enqueued and workers stop pulling jobs to be worked. If I restart Solid Queue (rake solid_queue:start) then the jobs are immediately worked.

This happens with both recurring jobs as well as jobs that are "perform_later".

Starting the solid queue looks all good and there aren't any subsequent log items that indicate any issues.

cc@Mac-mini funstuff % rake solid_queue:start
[SolidQueue] Starting Dispatcher(pid=76984, hostname=Mac-mini.local, metadata={:polling_interval=>1, :batch_size=>500, :concurrency_maintenance_interval=>600, :recurring_schedule=>{:"Expire subs"=>{:schedule=>"every day at 00:01", :class_name=>"ExpireSubsJob", :arguments=>[]}, :send_notifications_subs_expired=>{:schedule=>"every day at 00:15", :class_name=>"SendSubsExpirationNotificationJob", :arguments=>[]}, :send_notifications_subs_expiring=>{:schedule=>"every day at 10:00am", :class_name=>"SendSubsExpiringIn7DaysEmailJob", :arguments=>[]}, :"Send new posts email"=>{:schedule=>"every weekday at 5:00, 8:00, 11:00, 13:00, 15:00", :class_name=>"SendNewPostsEmailJob", :arguments=>[]}, :"Identify posts"=>{:schedule=>"every hour at minute 5", :class_name=>"IdentifyPostsJob", :arguments=>[]}, :"Add posts to Profiles"=>{:schedule=>"every 10 minutes", :class_name=>"ProcessNewPostsToProfilesJob", :arguments=>[]}, :"Destroy incomplete Posts"=>{:schedule=>"every day at 7:00am", :class_name=>"CleanUpPostsJob", :arguments=>[]}}})
[SolidQueue] Starting Worker(pid=76985, hostname=Mac-mini.local, metadata={:polling_interval=>1, :queues=>"*", :thread_pool_size=>3})

The only setting in my development.rb:
config.active_job.queue_adapter = :solid_queue

Solid Queue: 0.3.0
Rails: 7.1.3.2

[rosa]

Hey @carsoncole, sorry about that! Could you share a bit more about your DB setup? Also, could you try setting this:

config.solid_queue.silence_polling = false

And then starting solid_queue:start again? That might give us more clues about what's going on.

[ekampp]

I was seeing the same problem. Disabling polling silence seems to trigger it to work properly.

It turns out that it only works until a ruby file is changed.

[carsoncole]

@rosa Overnight, jobs stopped executing again. I set silence_polling = false. I've included the logs at the moment a job was created and enqueued. This is all running in development on my local Mac.

 SolidQueue::ScheduledExecution Pluck (3.0ms)  SELECT "solid_queue_scheduled_executions"."job_id" FROM "solid_queue_scheduled_executions" WHERE "solid_queue_scheduled_executions"."scheduled_at" <= $1 ORDER BY "solid_queue_scheduled_executions"."scheduled_at" ASC, "solid_queue_scheduled_executions"."priority" ASC, "solid_queue_scheduled_executions"."job_id" ASC LIMIT $2 FOR UPDATE SKIP LOCKED  [["scheduled_at", "2024-04-11 15:19:59.498234"], ["LIMIT", 500]]

  TRANSACTION (0.1ms)  COMMIT
[ActiveJob]   TRANSACTION (0.2ms)  BEGIN
[ActiveJob]   SolidQueue::Job Create (2.5ms)  INSERT INTO "solid_queue_jobs" ("queue_name", "class_name", "arguments", "priority", "active_job_id", "scheduled_at", "finished_at", "concurrency_key", "created_at", "updated_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10) RETURNING "id"  [["queue_name", "default"], ["class_name", "ProcessNewJobsToProfilesJob"], ["arguments", "{\"job_class\":\"ProcessNewJobsToProfilesJob\",\"job_id\":\"5fc05678-dbf5-45e6-81d6-f925734589f5\",\"provider_job_id\":null,\"queue_name\":\"default\",\"priority\":null,\"arguments\":[],\"executions\":0,\"exception_executions\":{},\"locale\":\"en\",\"timezone\":\"Pacific Time (US \\u0026 Canada)\",\"enqueued_at\":\"2024-04-11T15:20:00.008251000Z\",\"scheduled_at\":\"2024-04-11T15:20:00.008202000Z\"}"], ["priority", 0], ["active_job_id", "5fc05678-dbf5-45e6-81d6-f925734589f5"], ["scheduled_at", "2024-04-11 15:20:00.008202"], ["finished_at", nil], ["concurrency_key", "[FILTERED]"], ["created_at", "2024-04-11 15:20:00.008732"], ["updated_at", "2024-04-11 15:20:00.008732"]]
[ActiveJob]   TRANSACTION (0.2ms)  SAVEPOINT active_record_1
[ActiveJob]   SolidQueue::Job Load (0.2ms)  SELECT "solid_queue_jobs".* FROM "solid_queue_jobs" WHERE "solid_queue_jobs"."id" = $1 LIMIT $2  [["id", 907], ["LIMIT", 1]]
[ActiveJob]   SolidQueue::ReadyExecution Create (0.7ms)  INSERT INTO "solid_queue_ready_executions" ("job_id", "queue_name", "priority", "created_at") VALUES ($1, $2, $3, $4) RETURNING "id"  [["job_id", 907], ["queue_name", "default"], ["priority", 0], ["created_at", "2024-04-11 15:20:00.017665"]]
[ActiveJob]   TRANSACTION (0.1ms)  RELEASE SAVEPOINT active_record_1
[ActiveJob]   Log Create (0.4ms)  INSERT INTO "logs" ("status", "log_class", "class_id", "message", "request", "response_code", "source_id", "created_at", "updated_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9) RETURNING "id"  [["status", 0], ["log_class", "ProcessNewJobsToProfilesJob"], ["class_id", nil], ["message", "Job #5fc0567 enqueued"], ["request", nil], ["response_code", nil], ["source_id", nil], ["created_at", "2024-04-11 15:20:00.020842"], ["updated_at", "2024-04-11 15:20:00.020842"]]
[ActiveJob]   ↳ app/jobs/application_job.rb:9:in `block in <class:ApplicationJob>'
[ActiveJob] Enqueued ProcessNewJobsToProfilesJob (Job ID: 5fc05678-dbf5-45e6-81d6-f925734589f5) to SolidQueue(default)
  SolidQueue::Job Load (0.1ms)  SELECT "solid_queue_jobs".* FROM "solid_queue_jobs" WHERE "solid_queue_jobs"."id" = $1 LIMIT $2  [["id", 907], ["LIMIT", 1]]
  SolidQueue::RecurringExecution Create (0.6ms)  INSERT INTO "solid_queue_recurring_executions" ("job_id", "task_key", "run_at", "created_at") VALUES ($1, $2, $3, $4) RETURNING "id"  [["job_id", 907], ["task_key", "[FILTERED]"], ["run_at", "2024-04-11 15:20:00"], ["created_at", "2024-04-11 15:20:00.023454"]]
  TRANSACTION (1.5ms)  COMMIT
  Rendered admin/logs/_log.html.erb (Duration: 0.3ms | Allocations: 73)
[ActionCable] Broadcasting to logs: "<turbo-stream action=\"prepend\" target=\"logs\"><template><tr id=\"log_2893\" class=\"border-b\">\n  <td class=\"px-2 py-2 w-16 text-center dark:text-slate-700\">\n    <div class='rounded font-bold text-xs px-2 py-1 bg-blue-200'>INFO</div>\n  </td>\n  <td class=\"px-2 py-2\">\n    ProcessNewJob...
  TRANSACTION (0.2ms)  BEGIN
  SolidQueue::ScheduledExecution Pluck (1.9ms)  SELECT "solid_queue_scheduled_executions"."job_id" FROM "solid_queue_scheduled_executions" WHERE "solid_queue_scheduled_executions"."scheduled_at" <= $1 ORDER BY "solid_queue_scheduled_executions"."scheduled_at" ASC, "solid_queue_scheduled_executions"."priority" ASC, "solid_queue_scheduled_executions"."job_id" ASC LIMIT $2 FOR UPDATE SKIP LOCKED  [["scheduled_at", "2024-04-11 15:20:00.507423"], ["LIMIT", 500]]
  TRANSACTION (0.1ms)  COMMIT
  TRANSACTION (0.3ms)  BEGIN
  SolidQueue::ScheduledExecution Pluck (3.2ms)  SELECT "solid_queue_scheduled_executions"."job_id" FROM "solid_queue_scheduled_executions" WHERE "solid_queue_scheduled_executions"."scheduled_at" <= $1 ORDER BY "solid_queue_scheduled_executions"."scheduled_at" ASC, "solid_queue_scheduled_executions"."priority" ASC, "solid_queue_scheduled_executions"."job_id" ASC LIMIT $2 FOR UPDATE SKIP LOCKED  [["scheduled_at", "2024-04-11 15:20:01.515209"], ["LIMIT", 500]]

In the Solid Queue console here is the output since I launched it, which I notice undefined method queue_adapter_name' for nil:NilClass`...

carsoncole@Carsons-Mac-mini ahoyjob % rake solid_queue:start
[SolidQueue] Starting Dispatcher(pid=90937, hostname=Carsons-Mac-mini.local, metadata={:polling_interval=>1, :batch_size=>500, :concurrency_maintenance_interval=>600, :recurring_schedule=>{:"Expire subscriptions"=>{:schedule=>"every day at 00:01", :class_name=>"ExpireSubscriptionsJob", :arguments=>[]}, :send_notifications_subscriptions_expired=>{:schedule=>"every day at 00:15", :class_name=>"SendSubscriptionExpirationNotificationJob", :arguments=>[]}, :send_notifications_subscriptions_expiring=>{:schedule=>"every day at 10:00am", :class_name=>"SendSubscriptionExpiringIn7DaysEmailJob", :arguments=>[]}, :"Send new jobs email"=>{:schedule=>"every weekday at 5:00, 8:00, 11:00, 13:00, 15:00", :class_name=>"SendNewJobsEmailJob", :arguments=>[]}, :"Identify jobs"=>{:schedule=>"every 30 minutes at minute 5", :class_name=>"IdentifyJobsJob", :arguments=>[]}, :"Add jobs to Profiles"=>{:schedule=>"every 10 minutes", :class_name=>"ProcessNewJobsToProfilesJob", :arguments=>[]}, :"Destroy incomplete Jobs"=>{:schedule=>"every day at 7:00am", :class_name=>"CleanUpJobsJob", :arguments=>[]}, :"Clean up incomplete Jobs"=>{:schedule=>"every 4 hours at minute 45", :class_name=>"CleanUpIncompleteJobs", :arguments=>[]}}})
[SolidQueue] Starting Worker(pid=90938, hostname=Carsons-Mac-mini.local, metadata={:polling_interval=>1, :queues=>"*", :thread_pool_size=>3})
[SolidQueue] undefined method `queue_adapter_name' for nil:NilClass
[SolidQueue] Skipped recurring task Add jobs to Profiles at 2024-04-11 08:20:00 UTC — already dispatched
[SolidQueue] Skipped recurring task Identify jobs at 2024-04-11 08:30:00 UTC — already dispatched
[SolidQueue] Skipped recurring task Identify jobs at 2024-04-11 09:30:00 UTC — already dispatched
[SolidQueue] Skipped recurring task Add jobs to Profiles at 2024-04-11 09:30:00 UTC — already dispatched
[SolidQueue] undefined method `queue_adapter_name' for nil:NilClass
[SolidQueue] undefined method `queue_adapter_name' for nil:NilClass
[SolidQueue] Skipped recurring task Send new jobs email at 2024-04-11 12:00:00 UTC — already dispatched
[SolidQueue] Skipped recurring task Destroy incomplete Jobs at 2024-04-11 14:00:00 UTC — already dispatched
[SolidQueue] Skipped recurring task Add jobs to Profiles at 2024-04-11 14:20:00 UTC — already dispatched
[SolidQueue] Skipped recurring task Identify jobs at 2024-04-11 14:30:00 UTC — already dispatched

Also, I'm seeing 8 records in the table solid_queue_ready_executions. Are these the jobs that are ready to be executed but aren't being executed?

[carsoncole]

Another recurring job just added. It's in the table solid_queue_recurring_executions and I see it as an entry in solid_queue_ready_executions, but in the log I only see the constant query SELECT "solid_queue_scheduled_executions" around the time the job is created.

[rosa]

Thanks for all this extra info! All the logs correspond to the dispatcher, it's as if the worker wasn't doing anything 🤔 The errors

[SolidQueue] undefined method `queue_adapter_name' for nil:NilClass

aren't related to jobs not being processed; they correspond to recurring tasks whose job class might not be defined. I need to improve this to show a better error in that case and don't try to dispatch the task, but you can ignore the errors for now.

Could you share a bit more about your DB setup?

[carsoncole]

database.yml

default: &default
  adapter: postgresql
  encoding: unicode
  pool: <%= ENV.fetch("RAILS_MAX_THREADS") { 5 } %>

development:
  <<: *default
  database: ahoyjob_development

This may be relevant, I'm using Postgresql for Action Cable

cable.yml

development:
  adapter: postgresql

test:
  adapter: test

production:
  adapter: postgresql

[carsoncole]

Another datapoint is that I have a Job class in my app that represents jobs, ie. developer, bus driver etc.

[carsoncole]

So through my test case below, I can trigger the undefined method `queue_adapter_name' for nil:NilClass with an incorrectly named class.

solid_queue.yml

  "Test Job":
    class: Testjob
    schedule: every minute

Job file was named testjob.rb and the class name was TestJob

I've fixed that now and running again to see if that has anything to do with not working jobs.

[carsoncole]

It does appear that the SolidQueue::ReadyExecution just dies and does not give any indication of why. In my logs it is executing at its interval of 1 second, and then stops. Here in my logs you see it actually finds a record when doing

SolidQueue::ReadyExecution Pluck (2.5ms)  SELECT "solid_queue_ready_executions"."job_id" FROM "solid_queue_ready_executions" ORDER BY "solid_queue_ready_executions"."priority" ASC, "solid_queue_ready_executions"."job_id" ASC LIMIT $1 FOR UPDATE SKIP LOCKED  [["LIMIT", 3]]

But then stops. Here is the full log and after the last entry for SELECT solid_queue_ready_executions it no longer makes the call.

 SolidQueue::Job Load (0.2ms)  SELECT "solid_queue_jobs".* FROM "solid_queue_jobs" WHERE "solid_queue_jobs"."id" = $1 LIMIT $2  [["id", 930], ["LIMIT", 1]]
  SolidQueue::RecurringExecution Create (1.4ms)  INSERT INTO "solid_queue_recurring_executions" ("job_id", "task_key", "run_at", "created_at") VALUES ($1, $2, $3, $4) RETURNING "id"  [["job_id", 930], ["task_key", "[FILTERED]"], ["run_at", "2024-04-11 17:50:00"], ["created_at", "2024-04-11 17:50:00.141010"]]
  TRANSACTION (0.4ms)  COMMIT
  Rendered admin/logs/_log.html.erb (Duration: 0.6ms | Allocations: 576)
[ActionCable] Broadcasting to logs: "<turbo-stream action=\"prepend\" target=\"logs\"><template><tr id=\"log_2970\" class=\"border-b\">\n  <td class=\"px-2 py-2 w-16 text-center dark:text-slate-700\">\n    <div class='rounded font-bold text-xs px-2 py-1 bg-blue-200'>INFO</div>\n  </td>\n  <td class=\"px-2 py-2\">\n    ProcessNewJob...
  SolidQueue::Pause Pluck (0.9ms)  SELECT "solid_queue_pauses"."queue_name" FROM "solid_queue_pauses"
  TRANSACTION (0.2ms)  BEGIN
  SolidQueue::ReadyExecution Pluck (2.5ms)  SELECT "solid_queue_ready_executions"."job_id" FROM "solid_queue_ready_executions" ORDER BY "solid_queue_ready_executions"."priority" ASC, "solid_queue_ready_executions"."job_id" ASC LIMIT $1 FOR UPDATE SKIP LOCKED  [["LIMIT", 3]]
  SolidQueue::ClaimedExecution Insert (1.9ms)  INSERT INTO "solid_queue_claimed_executions" ("job_id","process_id","created_at") VALUES (930, 148, CURRENT_TIMESTAMP) RETURNING "id"
  SolidQueue::ClaimedExecution Load (0.4ms)  SELECT "solid_queue_claimed_executions".* FROM "solid_queue_claimed_executions" WHERE "solid_queue_claimed_executions"."job_id" = $1 AND "solid_queue_claimed_executions"."process_id" = $2  [["job_id", 930], ["process_id", 148]]
  SolidQueue::ReadyExecution Delete All (1.3ms)  DELETE FROM "solid_queue_ready_executions" WHERE "solid_queue_ready_executions"."job_id" = $1  [["job_id", 930]]
  TRANSACTION (0.4ms)  COMMIT
  SolidQueue::Pause Pluck (0.8ms)  SELECT "solid_queue_pauses"."queue_name" FROM "solid_queue_pauses"
  TRANSACTION (1.0ms)  BEGIN
  SolidQueue::ReadyExecution Pluck (2.7ms)  SELECT "solid_queue_ready_executions"."job_id" FROM "solid_queue_ready_executions" ORDER BY "solid_queue_ready_executions"."priority" ASC, "solid_queue_ready_executions"."job_id" ASC LIMIT $1 FOR UPDATE SKIP LOCKED  [["LIMIT", 2]]
  TRANSACTION (0.4ms)  COMMIT
  SolidQueue::Job Load (0.8ms)  SELECT "solid_queue_jobs".* FROM "solid_queue_jobs" WHERE "solid_queue_jobs"."id" = $1 LIMIT $2  [["id", 930], ["LIMIT", 1]]
  TRANSACTION (0.2ms)  BEGIN
  SolidQueue::ScheduledExecution Pluck (1.8ms)  SELECT "solid_queue_scheduled_executions"."job_id" FROM "solid_queue_scheduled_executions" WHERE "solid_queue_scheduled_executions"."scheduled_at" <= $1 ORDER BY "solid_queue_scheduled_executions"."scheduled_at" ASC, "solid_queue_scheduled_executions"."priority" ASC, "solid_queue_scheduled_executions"."job_id" ASC LIMIT $2 FOR UPDATE SKIP LOCKED  [["scheduled_at", "2024-04-11 17:50:01.129034"], ["LIMIT", 500]]
  TRANSACTION (0.1ms)  COMMIT
  TRANSACTION (0.2ms)  BEGIN
  SolidQueue::ScheduledExecution Pluck (1.6ms)  SELECT "solid_queue_scheduled_executions"."job_id" FROM "solid_queue_scheduled_executions" WHERE "solid_queue_scheduled_executions"."scheduled_at" <= $1 ORDER BY "solid_queue_scheduled_executions"."scheduled_at" ASC, "solid_queue_scheduled_executions"."priority" ASC, "solid_queue_scheduled_executions"."job_id" ASC LIMIT $2 FOR UPDATE SKIP LOCKED  [["scheduled_at", "2024-04-11 17:50:02.138170"], ["LIMIT", 500]]

[SjoerdL]

We noticed a similar issue in our setup. I couldn't reproduce it with a clean Rails app, so that makes it harder to debug. For us, we could reliably reproduce the issue in the following way:

1. Checkout a branch
2. Start solidqueue
3. Run anything that enqueues a job
   => This works fine. Solidqueue claims the job and executes it
4. Checkout a different branch (which diverged from 1)
   => we see a code reload in solidqueue
5. Run the same job from 3
   => This doesn't work anymore. Solidqueue claims the job, but it doesn't get executed

We use a default configuration of solidqueue. I tried to dive into it a bit further. I found that solidqueue picked up the job and dispatches it to ActiveSupport. Here it gets stuck in executing before callbacks. It gets very hairy here for me to understand what is going on, but it seemed that one of the before callbacks tries to obtain a ShareLock, which is already held by a dead solidqueue worker. So the before callback never acquires the lock, and therefore keeps waiting indefinetely.

{#<Thread:0x000000010fc929e8@io-worker-1 /Users/myname/.asdf/installs/ruby/3.2.2/lib/ruby/gems/3.2.0/gems/concurrent-ruby-1.2.3/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:345 dead>=>[nil, [:load, false]]}

This specific thread was started by launch_process_prune. I am thinking that a code reload somehow kills this worker thread, but I can't really figure out why or what should be done to prevent it.

[rosa]

@carsoncole thanks for all these extra details 🙏🏻 @SjoerdL, that's super helpful! I'll try to investigate a bit more today, and see if I can get to to bottom of this 🔍💪🏻

[carsoncole]

I got the issue to show itself quickly by changing the threads to 1. To hide the issue longer, increase the number of threads.

  workers:
    - queues: "*"
      threads: 1
      processes: 1
      polling_interval: 1

[carldr]

I'm experiencing a similar problem too, and is reliably caused in development mode by saving any Ruby file in my Rails project. As soon as I do, new jobs are picked up but never finish, and I have to ctrl+c solid queue and re-start it. If I don't save a file, Solid Queue will continue to work fine for hours.

I've not checked if they actually run or not before getting stuck, I came across this issue while investigating whether I'd setup something up incorrectly, but this seems very similar behaviour to what @SjoerdL is experiencing.

[ekampp]

Hey, @rosa, thanks for digging into this one!