rails / solid_queue

Database-backed Active Job backend
MIT License
1.66k stars 90 forks source link

Solid Queue isn't processing jobs in queues #253

Closed JuzerShakir closed 1 week ago

JuzerShakir commented 1 week ago

This is my first time using the Solid Queue library and I am using it in my project to send emails to the users at a particular date.

To setup the library with my existing project I followed the instructions provided in it's README file and also went through couple of videos from the GoRails & Webcrunch.

So once the database is set up with the Solid Queue tables, I created a Job class that commits the jobs to a solid queue table once I trigger perform_later function.

For example:

WishBirthdayBuddyJob.set(wait_until: Time.now + 1.minute).perform_later

And this is the output it returns:

TRANSACTION (0.1ms)  begin transaction
  SolidQueue::Job Create (0.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 (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) RETURNING "id"  [["queue_name", "default"], ["class_name", "WishBirthdayBuddyJob"], ["arguments", "{\"job_class\":\"WishBirthdayBuddyJob\",\"job_id\":\"3afbb65b-616d-40cf-acaa-78f92508bb14\",\"provider_job_id\":null,\"queue_name\":\"default\",\"priority\":null,\"arguments\":[],\"executions\":0,\"exception_executions\":{},\"locale\":\"en\",\"timezone\":\"UTC\",\"enqueued_at\":\"2024-07-07T07:11:54.335187513Z\",\"scheduled_at\":\"2024-07-07T07:12:54.312752723Z\"}"], ["priority", 0], ["active_job_id", "3afbb65b-616d-40cf-acaa-78f92508bb14"], ["scheduled_at", "2024-07-07 07:12:54.312752"], ["finished_at", nil], ["concurrency_key", "[FILTERED]"], ["created_at", "2024-07-07 07:11:54.367836"], ["updated_at", "2024-07-07 07:11:54.367836"]]
  TRANSACTION (0.1ms)  SAVEPOINT active_record_1
  SolidQueue::Job Load (0.2ms)  SELECT "solid_queue_jobs".* FROM "solid_queue_jobs" WHERE "solid_queue_jobs"."id" = ? LIMIT ?  [["id", 5], ["LIMIT", 1]]
  SolidQueue::ScheduledExecution Create (0.1ms)  INSERT INTO "solid_queue_scheduled_executions" ("job_id", "queue_name", "priority", "scheduled_at", "created_at") VALUES (?, ?, ?, ?, ?) RETURNING "id"  [["job_id", 5], ["queue_name", "default"], ["priority", 0], ["scheduled_at", "2024-07-07 07:12:54.312752"], ["created_at", "2024-07-07 07:11:54.387819"]]
  TRANSACTION (0.0ms)  RELEASE SAVEPOINT active_record_1
  TRANSACTION (0.2ms)  commit transaction
Enqueued WishBirthdayBuddyJob (Job ID: 3afbb65b-616d-40cf-acaa-78f92508bb14) to SolidQueue(default) at 2024-07-07 07:12:54 UTC
 => 
#<WishBirthdayBuddyJob:0x0000707f33d8bf58
 @_halted_callback_hook_called=nil,
 @_scheduled_at_time=2024-07-07 07:12:54 327945/1048576 UTC,
 @arguments=[],
 @exception_executions={},
 @executions=0,
 @job_id="3afbb65b-616d-40cf-acaa-78f92508bb14",
 @priority=nil,
 @provider_job_id=5,
 @queue_name="default",
 @scheduled_at=2024-07-07 07:12:54 327945/1048576 UTC,
 @successfully_enqueued=true,
 @timezone="UTC"> 

So the job is successfully queued in and it's ready to run after we start listening to it with this command:

bundle exec rake solid_queue:start 

But running this command doesn't output anything in my console, the cursor just blinks in the next line. After a few seconds, I hit Ctrl+Z to stop the execution. (Ctrl + C won't output anything)

Screenshot from 2024-07-07 12-49-23

The configuration file config/solid_queue.yml is initialized by the solid queue on setup and comes with the default configurations. I haven't changed anything in it and looks like this:

default: &default
  dispatchers:
    - polling_interval: 1
      batch_size: 500
  workers:
    - queues: "*"
      threads: 3
      processes: 1
      polling_interval: 0.1

development:
  <<: *default

test:
  <<: *default

production:
  <<: *default
  1. I went through the issues tab of this repo but couldn't find anything related to this

  2. I also tried to delete the database and re-run the migrations but the result is the same.

  3. I also restarted my Terminator and laptop just to make sure that it isn't system-specific.

  4. I also went ahead and created a new rails app and integrated the solid queue backend in it but the result is the same, however when hitting Ctrl+C to stop the execution it returns this error:

    ^C/usr/share/rvm/gems/ruby-3.3.1/gems/sqlite3-1.7.3-x86_64-linux/lib/sqlite3/statement.rb:108:in `step': SQLite3::BusyException: database is locked (ActiveRecord::StatementInvalid)
    from /usr/share/rvm/gems/ruby-3.3.1/gems/sqlite3-1.7.3-x86_64-linux/lib/sqlite3/statement.rb:108:in `block in each'
    from <internal:kernel>:187:in `loop'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/sqlite3-1.7.3-x86_64-linux/lib/sqlite3/statement.rb:107:in `each'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/sqlite3/database_statements.rb:42:in `to_a'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/sqlite3/database_statements.rb:42:in `block (2 levels) in internal_exec_query'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract_adapter.rb:1028:in `block in with_raw_connection'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract_adapter.rb:1000:in `with_raw_connection'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/sqlite3/database_statements.rb:33:in `block in internal_exec_query'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract_adapter.rb:1143:in `log'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/sqlite3/database_statements.rb:32:in `internal_exec_query'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/sqlite3/database_statements.rb:61:in `exec_delete'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/database_statements.rb:208:in `delete'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/query_cache.rb:25:in `delete'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/persistence.rb:624:in `_delete_record'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/persistence.rb:1198:in `_delete_row'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/persistence.rb:1194:in `destroy_row'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/counter_cache.rb:197:in `destroy_row'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/locking/optimistic.rb:125:in `destroy_row'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/persistence.rb:783:in `destroy'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/callbacks.rb:423:in `block in destroy'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:110:in `run_callbacks'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:952:in `_run_destroy_callbacks'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/callbacks.rb:423:in `destroy'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/transactions.rb:305:in `block in destroy'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/transactions.rb:365:in `block in with_transaction_returning_status'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/transaction.rb:535:in `block in within_new_transaction'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/transaction.rb:532:in `within_new_transaction'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/connection_adapters/abstract/database_statements.rb:344:in `transaction'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/transactions.rb:361:in `with_transaction_returning_status'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/transactions.rb:305:in `destroy'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activerecord-7.1.3.4/lib/active_record/persistence.rb:797:in `destroy!'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/app/models/solid_queue/process.rb:29:in `block in deregister'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:206:in `block in instrument'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:206:in `instrument'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue.rb:59:in `instrument'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/app/models/solid_queue/process.rb:28:in `deregister'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue/processes/registrable.rb:27:in `deregister'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:403:in `block in make_lambda'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:239:in `block in halting_and_conditional'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:602:in `block in invoke_after'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:602:in `each'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:602:in `invoke_after'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/callbacks.rb:111:in `run_callbacks'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue/processes/poller.rb:38:in `block in start_loop'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:206:in `block in instrument'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/activesupport-7.1.3.4/lib/active_support/notifications.rb:206:in `instrument'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue.rb:59:in `instrument'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue/processes/poller.rb:37:in `start_loop'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue/processes/poller.rb:22:in `run'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue/processes/runnable.rb:16:in `start'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue/supervisor.rb:124:in `block in start_fork'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue/supervisor.rb:123:in `fork'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue/supervisor.rb:123:in `start_fork'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue/supervisor.rb:65:in `block in start_forks'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue/supervisor.rb:65:in `each'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue/supervisor.rb:65:in `start_forks'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue/supervisor.rb:24:in `start'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue/supervisor.rb:12:in `start'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/solid_queue-0.3.3/lib/solid_queue/tasks.rb:4:in `block (2 levels) in <main>'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/task.rb:281:in `block in execute'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/task.rb:281:in `each'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/task.rb:281:in `execute'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/task.rb:219:in `block in invoke_with_call_chain'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/task.rb:199:in `synchronize'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/task.rb:199:in `invoke_with_call_chain'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/task.rb:188:in `invoke'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/application.rb:188:in `invoke_task'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/application.rb:138:in `block (2 levels) in top_level'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/application.rb:138:in `each'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/application.rb:138:in `block in top_level'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/application.rb:147:in `run_with_threads'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/application.rb:132:in `top_level'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/application.rb:83:in `block in run'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/application.rb:214:in `standard_exception_handling'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/lib/rake/application.rb:80:in `run'
    from /usr/share/rvm/gems/ruby-3.3.1/gems/rake-13.2.1/exe/rake:27:in `<top (required)>'
    from /usr/share/rvm/gems/ruby-3.3.1/bin/rake:25:in `load'
    from /usr/share/rvm/gems/ruby-3.3.1/bin/rake:25:in `<main>'
    from /usr/share/rvm/gems/ruby-3.3.1/bin/ruby_executable_hooks:22:in `eval'
    from /usr/share/rvm/gems/ruby-3.3.1/bin/ruby_executable_hooks:22:in `<main>'

    And this wasn't the case in my existing project.

So here's the tech stack of my project: Ruby: 3.3.1 Rails: 7.1.3.4 SQLite: 1.7.3 (Using the litedb adapter to use SQLite database in Fly.io)

And here's the database.yml file in case you're interested:

# SQLite. Versions 3.8.0 and up are supported.
#   gem install sqlite3
#
#   Ensure the SQLite 3 gem is defined in your Gemfile
#   gem "sqlite3"
#
# `Litesupport.root.join("data.sqlite3")` stores
# application data in the path `./db/#{Rails.env}/data.sqlite3`
#
# `Litesupport.root(env).join(path)` stores 
# application data in the path `./db/#{env}/#{path}`
#
# idle_timeout should be set to zero, to avoid recycling sqlite connections
# and losing the page cache
# 
default: &default
  adapter: litedb
  pool: <%= ENV.fetch("RAILS_MAX_THREADS") { 5 } %>
  idle_timeout: 0

development:
  <<: *default
  database: <%= Litesupport.root("development").join("data.sqlite3") %>

# Warning: The database defined as "test" will be erased and
# re-generated from your development database when you run "rake".
# Do not set this db to the same as development or production.
test:
  <<: *default
  database: <%= Litesupport.root("test").join("data.sqlite3") %>

# Warning: Make sure your production database path is on a persistent
# volume, otherwise your application data could be deleted between deploys.
#
# You may also set the Litesupport.root in production via the
# `LITESTACK_DATA_PATH` environment variable.
production:
  <<: *default
  database: <%= Litesupport.root("production").join("data.sqlite3") %>

And yes I have added configuration in the development.rb file to execute jobs via solid_queue.

Has anyone encountered this issue? If yes, or know why this happened, your help would be deeply appreciated. Thanks! :)

JuzerShakir commented 1 week ago

Running bundle exec rake solid_queue:start cmd no longer outputs anything in the console but listens to the enqueued jobs and executes them.

To ensure that, we can inspect the SQLite file in any SQLite DB software and check the finished_at column in the solid_queue_jobs table. It will be populated with a timestamp of when the execution of the job was finished and the jobs that are scheduled for a later time can also be found in the solid_queue_scheduled_executions table.

But if you still prefer console logs for this over manually checking the db file then the Puma plugin is the way to go. As mentioned in the README.md file, add plugin: solid_queue to the puma.rb file and this will not only listen to jobs while running the server but also print out logs in both the development & production environment. And I would prefer this any day.

rosa commented 1 week ago

Hey @JuzerShakir, thanks for figuring this out! Logs in development are sent to Rails.logger by default. I think you might find those, if you haven't changed this, in log/development.log. See https://github.com/rails/solid_queue/issues/238.