Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

deregistering process issues? #108

Closed
davidpan opened this issue Dec 31, 2023 · 17 comments · May be fixed by #119
Closed

deregistering process issues? #108

davidpan opened this issue Dec 31, 2023 · 17 comments · May be fixed by #119

Comments

@davidpan
Copy link

After running 'bundle exec rake solid_queue:start' for a while and stopping it with Ctrl-C, I noticed that the record of stopped processes in the 'solid_queue_processes' table was not deleted.

Upon restarting, I received an error message stating 'deregistering process 1 - {}' and the corresponding record still existed in the table.

@rosa
Copy link
Member

rosa commented Dec 31, 2023

Hey @davidpan, I can't reproduce this 😕 Processes are correctly deregistered (deleted from solid_queue_processes) upon receiving a SIGINT signal via Ctrl-C. Could you share more about your configuration and environment?

@davidpan
Copy link
Author

davidpan commented Jan 1, 2024

Thanks for the reply.

run bin/rails solid_queue:start

[SolidQueue] Starting Dispatcher(pid=8537, hostname=Desktop, metadata={:polling_interval=>1, :batch_size=>500})
[SolidQueue] Starting Worker(pid=8539, hostname=Desktop, metadata={:polling_interval=>1, :queues=>"chrome_single", :thread_pool_size=>1})
[SolidQueue] Claimed 1 jobs
[SolidQueue] Dispatched scheduled batch with 1 jobs
^C[SolidQueue] Terminating gracefully...
[SolidQueue] Terminating immediately...
[SolidQueue] Error deregistering process 16 - {}
bin/rails aborted!
ActiveRecord::LockWaitTimeout: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction (ActiveRecord::LockWaitTimeout)
Caused by:
Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction (Mysql2::Error::TimeoutError)
Tasks: TOP => solid_queue:start
(See full trace by running task with --trace)

run bin/rails solid_queue:start --trace

** Invoke solid_queue:start (first_time)
** Invoke environment (first_time)
** Execute environment
** Execute solid_queue:start
[SolidQueue] Starting Dispatcher(pid=9419, hostname=Desktop, metadata={:polling_interval=>1, :batch_size=>500})
[SolidQueue] Starting Worker(pid=9421, hostname=Desktop, metadata={:polling_interval=>1, :queues=>"chrome_single", :thread_pool_size=>1})
[SolidQueue] Claimed 1 jobs
^C[SolidQueue] Terminating gracefully...
[SolidQueue] Terminating immediately...
[SolidQueue] Error deregistering process 22 - {}
bin/rails aborted!
ActiveRecord::LockWaitTimeout: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction (ActiveRecord::LockWaitTimeout)
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:151:in `_query'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:151:in `block in query'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:150:in `handle_interrupt'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:150:in `query'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/mysql2/database_statements.rb:100:in `block (2 levels) in raw_execute'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract_adapter.rb:1028:in `block in with_raw_connection'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract_adapter.rb:1000:in `with_raw_connection'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/mysql2/database_statements.rb:98:in `block in raw_execute'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract_adapter.rb:1143:in `log'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/mysql2/database_statements.rb:97:in `raw_execute'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:233:in `execute_and_free'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/mysql2/database_statements.rb:45:in `block in exec_delete'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract_adapter.rb:1028:in `block in with_raw_connection'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract_adapter.rb:1000:in `with_raw_connection'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/mysql2/database_statements.rb:43:in `exec_delete'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/database_statements.rb:208:in `delete'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/query_cache.rb:25:in `delete'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/persistence.rb:624:in `_delete_record'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/persistence.rb:1197:in `_delete_row'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/persistence.rb:1193:in `destroy_row'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/counter_cache.rb:197:in `destroy_row'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/locking/optimistic.rb:125:in `destroy_row'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/persistence.rb:783:in `destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/callbacks.rb:423:in `block in destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:110:in `run_callbacks'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:952:in `_run_destroy_callbacks'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/callbacks.rb:423:in `destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:305:in `block in destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:365:in `block in with_transaction_returning_status'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/database_statements.rb:342:in `transaction'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:361:in `with_transaction_returning_status'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:305:in `destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/persistence.rb:797:in `destroy!'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/has_many_association.rb:129:in `each'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/has_many_association.rb:129:in `delete_records'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/collection_association.rb:396:in `remove_records'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/collection_association.rb:387:in `block in delete_or_destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/database_statements.rb:342:in `transaction'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:212:in `transaction'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/collection_association.rb:314:in `transaction'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/collection_association.rb:387:in `delete_or_destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/collection_association.rb:194:in `destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/collection_association.rb:171:in `destroy_all'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/has_many_association.rb:29:in `handle_dependency'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/builder/association.rb:141:in `block in add_destroy_callbacks'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:470:in `instance_exec'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:470:in `block in make_lambda'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:202:in `block (2 levels) in halting'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:707:in `block (2 levels) in default_terminator'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:706:in `catch'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:706:in `block in default_terminator'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:203:in `block in halting'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:598:in `block in invoke_before'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:598:in `each'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:598:in `invoke_before'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:109:in `run_callbacks'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:952:in `_run_destroy_callbacks'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/callbacks.rb:423:in `destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:305:in `block in destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:365:in `block in with_transaction_returning_status'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/transaction.rb:535:in `block in within_new_transaction'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/transaction.rb:532:in `within_new_transaction'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/database_statements.rb:344:in `transaction'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:361:in `with_transaction_returning_status'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:305:in `destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/persistence.rb:797:in `destroy!'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/solid_queue-0.1.2/app/models/solid_queue/process.rb:23:in `deregister'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/solid_queue-0.1.2/lib/solid_queue/processes/registrable.rb:33:in `deregister'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:403:in `block in make_lambda'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:274:in `block in simple'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:602:in `block in invoke_after'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:602:in `each'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:602:in `invoke_after'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:111:in `run_callbacks'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/solid_queue-0.1.2/lib/solid_queue/supervisor.rb:32:in `start'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/solid_queue-0.1.2/lib/solid_queue/supervisor.rb:14:in `start'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/solid_queue-0.1.2/lib/solid_queue/tasks.rb:4:in `block (2 levels) in <main>'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/task.rb:281:in `block in execute'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/task.rb:281:in `each'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/task.rb:281:in `execute'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/bugsnag-6.26.0/lib/bugsnag/integrations/rake.rb:20:in `execute'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/task.rb:219:in `block in invoke_with_call_chain'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/task.rb:199:in `synchronize'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/task.rb:199:in `invoke_with_call_chain'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/task.rb:188:in `invoke'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/application.rb:182:in `invoke_task'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/application.rb:138:in `block (2 levels) in top_level'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/application.rb:138:in `each'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/application.rb:138:in `block in top_level'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/application.rb:147:in `run_with_threads'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/application.rb:132:in `top_level'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/commands/rake/rake_command.rb:27:in `block (2 levels) in perform'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/application.rb:208:in `standard_exception_handling'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/commands/rake/rake_command.rb:27:in `block in perform'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/commands/rake/rake_command.rb:44:in `block in with_rake'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/rake_module.rb:59:in `with_application'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/commands/rake/rake_command.rb:41:in `with_rake'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/commands/rake/rake_command.rb:20:in `perform'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/command.rb:156:in `invoke_rake'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/command.rb:73:in `block in invoke'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/command.rb:149:in `with_argv'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/command.rb:69:in `invoke'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/commands.rb:18:in `<main>'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/bootsnap-1.17.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/bootsnap-1.17.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
bin/rails:4:in `<main>'

Caused by:
Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction (Mysql2::Error::TimeoutError)
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:151:in `_query'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:151:in `block in query'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:150:in `handle_interrupt'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/mysql2-0.5.5/lib/mysql2/client.rb:150:in `query'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/mysql2/database_statements.rb:100:in `block (2 levels) in raw_execute'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract_adapter.rb:1028:in `block in with_raw_connection'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract_adapter.rb:1000:in `with_raw_connection'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/mysql2/database_statements.rb:98:in `block in raw_execute'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/notifications/instrumenter.rb:58:in `instrument'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract_adapter.rb:1143:in `log'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/mysql2/database_statements.rb:97:in `raw_execute'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract_mysql_adapter.rb:233:in `execute_and_free'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/mysql2/database_statements.rb:45:in `block in exec_delete'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract_adapter.rb:1028:in `block in with_raw_connection'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract_adapter.rb:1000:in `with_raw_connection'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/mysql2/database_statements.rb:43:in `exec_delete'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/database_statements.rb:208:in `delete'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/query_cache.rb:25:in `delete'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/persistence.rb:624:in `_delete_record'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/persistence.rb:1197:in `_delete_row'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/persistence.rb:1193:in `destroy_row'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/counter_cache.rb:197:in `destroy_row'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/locking/optimistic.rb:125:in `destroy_row'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/persistence.rb:783:in `destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/callbacks.rb:423:in `block in destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:110:in `run_callbacks'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:952:in `_run_destroy_callbacks'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/callbacks.rb:423:in `destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:305:in `block in destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:365:in `block in with_transaction_returning_status'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/database_statements.rb:342:in `transaction'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:361:in `with_transaction_returning_status'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:305:in `destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/persistence.rb:797:in `destroy!'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/has_many_association.rb:129:in `each'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/has_many_association.rb:129:in `delete_records'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/collection_association.rb:396:in `remove_records'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/collection_association.rb:387:in `block in delete_or_destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/database_statements.rb:342:in `transaction'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:212:in `transaction'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/collection_association.rb:314:in `transaction'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/collection_association.rb:387:in `delete_or_destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/collection_association.rb:194:in `destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/collection_association.rb:171:in `destroy_all'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/has_many_association.rb:29:in `handle_dependency'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/associations/builder/association.rb:141:in `block in add_destroy_callbacks'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:470:in `instance_exec'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:470:in `block in make_lambda'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:202:in `block (2 levels) in halting'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:707:in `block (2 levels) in default_terminator'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:706:in `catch'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:706:in `block in default_terminator'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:203:in `block in halting'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:598:in `block in invoke_before'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:598:in `each'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:598:in `invoke_before'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:109:in `run_callbacks'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:952:in `_run_destroy_callbacks'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/callbacks.rb:423:in `destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:305:in `block in destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:365:in `block in with_transaction_returning_status'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/transaction.rb:535:in `block in within_new_transaction'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/transaction.rb:532:in `within_new_transaction'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/connection_adapters/abstract/database_statements.rb:344:in `transaction'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:361:in `with_transaction_returning_status'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/transactions.rb:305:in `destroy'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activerecord-7.1.2/lib/active_record/persistence.rb:797:in `destroy!'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/solid_queue-0.1.2/app/models/solid_queue/process.rb:23:in `deregister'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/solid_queue-0.1.2/lib/solid_queue/processes/registrable.rb:33:in `deregister'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:403:in `block in make_lambda'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:274:in `block in simple'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:602:in `block in invoke_after'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:602:in `each'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:602:in `invoke_after'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/activesupport-7.1.2/lib/active_support/callbacks.rb:111:in `run_callbacks'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/solid_queue-0.1.2/lib/solid_queue/supervisor.rb:32:in `start'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/solid_queue-0.1.2/lib/solid_queue/supervisor.rb:14:in `start'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/solid_queue-0.1.2/lib/solid_queue/tasks.rb:4:in `block (2 levels) in <main>'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/task.rb:281:in `block in execute'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/task.rb:281:in `each'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/task.rb:281:in `execute'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/bugsnag-6.26.0/lib/bugsnag/integrations/rake.rb:20:in `execute'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/task.rb:219:in `block in invoke_with_call_chain'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/task.rb:199:in `synchronize'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/task.rb:199:in `invoke_with_call_chain'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/task.rb:188:in `invoke'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/application.rb:182:in `invoke_task'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/application.rb:138:in `block (2 levels) in top_level'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/application.rb:138:in `each'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/application.rb:138:in `block in top_level'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/application.rb:147:in `run_with_threads'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/application.rb:132:in `top_level'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/commands/rake/rake_command.rb:27:in `block (2 levels) in perform'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/application.rb:208:in `standard_exception_handling'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/commands/rake/rake_command.rb:27:in `block in perform'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/commands/rake/rake_command.rb:44:in `block in with_rake'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/rake-13.1.0/lib/rake/rake_module.rb:59:in `with_application'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/commands/rake/rake_command.rb:41:in `with_rake'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/commands/rake/rake_command.rb:20:in `perform'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/command.rb:156:in `invoke_rake'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/command.rb:73:in `block in invoke'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/command.rb:149:in `with_argv'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/command.rb:69:in `invoke'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/railties-7.1.2/lib/rails/commands.rb:18:in `<main>'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/bootsnap-1.17.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
/home/david/.rbenv/versions/3.2.2/lib/ruby/gems/3.2.0/gems/bootsnap-1.17.0/lib/bootsnap/load_path_cache/core_ext/kernel_require.rb:32:in `require'
bin/rails:4:in `<main>'
Tasks: TOP => solid_queue:start

environments:
Linux xxx-1 5.15.0-91-generic , Linux xxx 5.15.133.1-microsoft-standard-WSL2 Both environments are reproduced.

MySQL database version is: 8.0.35-0ubuntu0.22.04.1 (Ubuntu).

Project-related environments:
Ruby 3.2.2 (revision 2023-03-30 e51014f9c0)
Rails 7.1.2

Project-related gems:
mysql2 (0.5.5)
solid_queue (0.1.2)
selenium-webdriver (4.10.0)

solid_queue.yml file:

default: &default
  dispatchers:
    - polling_interval: 1
      batch_size: 500
      concurrency_maintenance_interval: 300
  workers:   
    - queues: "chrome_single"
      threads: 1
      processes: 1
      polling_interval: 1


development:
 <<: *default

test:
 <<: *default

production:
 <<: *default

jobs :

self.queue_adapter = :solid_queue
queue_as :chrome_single
limits_concurrency to: 1, key: ->(id) { id }, duration: 5.minutes

The job is accessing web pages to collect content using chrome's headless mode.

@rosa
Copy link
Member

rosa commented Jan 1, 2024

Thanks! That's very helpful as without the error I had no idea where to pull the thread from 😅 I've tried to reproduce this again, with a job that sleeps, but no luck.

Could you try that again, but with a longer shutdown timeout, that you can configure as:

config.solid_queue.shutdown_timeout = 60.seconds

and right after issuing Ctrl-C, run this via bin/rails dbconsole:

SHOW ENGINE INNODB STATUS\G
SELECT * FROM information_schema.innodb_trx\G

And copy the output?

@davidpan
Copy link
Author

davidpan commented Jan 1, 2024

After configuring for 60 seconds, retrying multiple times does not reproduce the error.
Is it possible that the default configuration parameters cannot wait long enough to complete the shutdown?

run log:

[SolidQueue] Starting Dispatcher(pid=773, hostname=Desktop, metadata={:polling_interval=>1, :batch_size=>500})
[SolidQueue] Starting Worker(pid=775, hostname=Desktop, metadata={:polling_interval=>1, :queues=>"chrome_single", :thread_pool_size=>1})
[SolidQueue] Claimed 1 jobs
^C[SolidQueue] Terminating gracefully...
[SolidQueue] Terminating immediately...

SHOW ENGINE INNODB STATUS:

*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2024-01-01 22:20:57 140031653017152 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 6 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 25 srv_active, 0 srv_shutdown, 573 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 38
OS WAIT ARRAY INFO: signal count 38
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 3030899
Purge done for trx's n:o < 3030899 undo n:o < 0 state: running but idle
History list length 11
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421507675692192, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421507675691384, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421507675690576, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421507675689768, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421507675694616, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421507675688960, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421507675688152, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421507675687344, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 421507675686536, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests ((null))
I/O thread 1 state: waiting for completed aio requests (insert buffer thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:
Pending flushes (fsync) log: 0; buffer pool: 0
1462 OS file reads, 1481 OS file writes, 1129 OS fsyncs
0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 3093, seg size 3095, 2 merges
merged operations:
 insert 2, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 4 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number          66020118976
Log buffer assigned up to    66020118976
Log buffer completed up to   66020118976
Log written up to            66020118976
Log flushed up to            66020118976
Added dirty pages up to      66020118976
Pages flushed up to          66020118976
Last checkpoint at           66020118976
Log minimum file id is       19809
Log maximum file id is       19809
391 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 0
Dictionary memory allocated 1149037
Buffer pool size   8192
Free buffers       6621
Database pages     1559
Old database pages 595
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 1414, created 145, written 746
0.00 reads/s, 0.00 creates/s, 0.00 writes/s
No buffer pool page gets since the last printout
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 1559, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
0 read views open inside InnoDB
Process ID=31493, Main thread ID=140032204682816 , state=sleeping
Number of rows inserted 22, updated 11, deleted 18, read 2943
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
Number of system rows inserted 8, updated 340, deleted 8, read 11480
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set (0.00 sec)

SELECT * FROM information_schema.innodb_trx:

Empty set (0.00 sec)

@rosa
Copy link
Member

rosa commented Jan 1, 2024

Hey @davidpan, no, it shouldn't make a difference with respect to the processes registration and deregistration. That would only affect jobs in-flight, and in your case, you're still using up all the time:

^C[SolidQueue] Terminating gracefully...
[SolidQueue] Terminating immediately...

My suspicion is that whatever transaction was open and locking your solid_queue_processes table is now gone, and the setting change is a mere coincidence. Try to see if you can reproduce it by going back to the default.

FWIW, I didn't touch shutdown_timeout when trying to reproduce it.

@davidpan
Copy link
Author

davidpan commented Jan 1, 2024

Undo the previous configuration change:

# config.solid_queue.shutdown_timeout = 60.seconds 

Retrying 2 times reproduces the problem. @rosa

Running logs on the command line:

[SolidQueue] Starting Dispatcher(pid=5786, hostname=Desktop, metadata={:polling_interval=>1, :batch_size=>500})
[SolidQueue] Starting Worker(pid=5788, hostname=Desktop, metadata={:polling_interval=>1, :queues=>"chrome_single", :thread_pool_size=>1})
[SolidQueue] Claimed 1 jobs
^C[SolidQueue] Terminating gracefully...
[SolidQueue] Terminating immediately...
[SolidQueue] Error deregistering process 43 - {}
bin/rails aborted!
ActiveRecord::LockWaitTimeout: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction (ActiveRecord::LockWaitTimeout)


Caused by:
Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction (Mysql2::Error::TimeoutError)

Tasks: TOP => solid_queue:start
(See full trace by running task with --trace)

SHOW ENGINE INNODB STATUS:

*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2024-01-02 07:48:18 140574684403264 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 30 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 18 srv_active, 0 srv_shutdown, 882 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 76
OS WAIT ARRAY INFO: signal count 76
RW-shared spins 0, rounds 0, OS waits 0
RW-excl spins 0, rounds 0, OS waits 0
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
------------
TRANSACTIONS
------------
Trx id counter 3031705
Purge done for trx's n:o < 3031349 undo n:o < 0 state: running but idle
History list length 28
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 422050137109176, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422050137105136, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
trx\G---TRANSACTION 422050137108368, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422050137100288, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422050137103520, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422050137102712, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422050137104328, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422050137099480, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422050137098672, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 422050137097864, not started
0 lock struct(s), heap size 1128, 0 row lock(s)
---TRANSACTION 3031704, ACTIVE 6 sec starting index read
mysql tables in use 1, locked 1
LOCK WAIT 2 lock struct(s), heap size 1128, 1 row lock(s)
MySQL thread id 27, OS thread handle 140574109693504, query id 1309 localhost 127.0.0.1 root updating
DELETE FROM `solid_queue_processes` WHERE `solid_queue_processes`.`id` = 44
Trx read view will not see trx with id >= 3031704, sees < 3031346
------- TRX HAS BEEN WAITING 6 SEC FOR THIS LOCK TO BE GRANTED:
RECORD LOCKS space id 584 page no 4 n bits 80 index PRIMARY of table `podcast`.`solid_queue_processes` trx id 3031704 lock_mode X locks rec but not gap waiting
Record lock, heap no 8 PHYSICAL RECORD: n_fields 10; compact format; info bits 32
 0: len 8; hex 800000000000002c; asc        ,;;
 1: len 6; hex 0000002e4293; asc    .B ;;
 2: len 7; hex 020000010d049c; asc        ;;
 3: len 6; hex 576f726b6572; asc Worker;;
 4: len 8; hex 99b2437bec08a7c3; asc   C{    ;;
 5: len 8; hex 800000000000002b; asc        +;;
 6: len 4; hex 8000169c; asc     ;;
 7: len 7; hex 4465736b746f70; asc Desktop;;
 8: len 30; hex 7b22706f6c6c696e675f696e74657276616c223a312c2271756575657322; asc {"polling_interval":1,"queues"; (total 65 bytes);
 9: len 8; hex 99b2437bec08bce1; asc   C{    ;;

------------------
---TRANSACTION 3031699, ACTIVE 6 sec
2 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 1
MySQL thread id 29, OS thread handle 140574550050368, query id 1305 localhost 127.0.0.1 root
Trx read view will not see trx with id >= 3031699, sees < 3031346
---TRANSACTION 3031346, ACTIVE 251 sec
2 lock struct(s), heap size 1128, 1 row lock(s), undo log entries 1
MySQL thread id 13, OS thread handle 140574556390976, query id 104 localhost 127.0.0.1 root
Trx read view will not see trx with id >= 3031346, sees < 3031346
--------
FILE I/O
--------
I/O thread 0 state: waiting for completed aio requests ((null))
I/O thread 1 state: waiting for completed aio requests (insert buffer thread)
I/O thread 2 state: waiting for completed aio requests (read thread)
I/O thread 3 state: waiting for completed aio requests (read thread)
I/O thread 4 state: waiting for completed aio requests (read thread)
I/O thread 5 state: waiting for completed aio requests (read thread)
I/O thread 6 state: waiting for completed aio requests (write thread)
I/O thread 7 state: waiting for completed aio requests (write thread)
I/O thread 8 state: waiting for completed aio requests (write thread)
Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
 ibuf aio reads:
Pending flushes (fsync) log: 0; buffer pool: 0
2860 OS file reads, 1324 OS file writes, 1092 OS fsyncs
0.06 reads/s, 16384 avg bytes/read, 6.37 writes/s, 5.69 fsyncs/s
-------------------------------------
INSERT BUFFER AND ADAPTIVE HASH INDEX
-------------------------------------
Ibuf: size 1, free list len 3093, seg size 3095, 1 merges
merged operations:
 insert 1, delete mark 0, delete 0
discarded operations:
 insert 0, delete mark 0, delete 0
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 4 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 2 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
7.40 hash searches/s, 10.53 non-hash searches/s
---
LOG
---
Log sequence number          66020416985
Log buffer assigned up to    66020416985
Log buffer completed up to   66020416985
Log written up to            66020416985
Log flushed up to            66020416985
Added dirty pages up to      66020416985
Pages flushed up to          66020416985
Last checkpoint at           66020416985
Log minimum file id is       19809
Log maximum file id is       19809
412 log i/o's done, 2.17 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 0
Dictionary memory allocated 1180781
Buffer pool size   8192
Free buffers       5473
Database pages     2707
Old database pages 1019
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 2563, created 144, written 571
0.06 reads/s, 0.00 creates/s, 2.69 writes/s
Buffer pool hit rate 999 / 1000, young-making rate 0 / 1000 not 0 / 1000
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
LRU len: 2707, unzip_LRU len: 0
I/O sum[0]:cur[0], unzip sum[0]:cur[0]
--------------
ROW OPERATIONS
--------------
0 queries inside InnoDB, 0 queries in queue
3 read views open inside InnoDB
Process ID=423, Main thread ID=140574598354496 , state=sleeping
Number of rows inserted 522, updated 3, deleted 12, read 123367
0.20 inserts/s, 0.00 updates/s, 0.10 deletes/s, 2.03 reads/s
Number of system rows inserted 8, updated 331, deleted 8, read 12457
0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 8.83 reads/s
----------------------------
END OF INNODB MONITOR OUTPUT
============================

1 row in set (0.00 sec)

SELECT * FROM information_schema.innodb_trx:

*************************** 1. row ***************************
                    trx_id: 3031704
                 trx_state: LOCK WAIT
               trx_started: 2024-01-02 07:48:12
     trx_requested_lock_id: 140575160390440:584:4:8:140575084967600
          trx_wait_started: 2024-01-02 07:48:12
                trx_weight: 2
       trx_mysql_thread_id: 27
                 trx_query: DELETE FROM `solid_queue_processes` WHERE `solid_queue_processes`.`id` = 44
       trx_operation_state: starting index read
         trx_tables_in_use: 1
         trx_tables_locked: 1
          trx_lock_structs: 2
     trx_lock_memory_bytes: 1128
           trx_rows_locked: 1
         trx_rows_modified: 0
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
 trx_adaptive_hash_latched: 0
 trx_adaptive_hash_timeout: 0
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
       trx_schedule_weight: 1
*************************** 2. row ***************************
                    trx_id: 3031699
                 trx_state: RUNNING
               trx_started: 2024-01-02 07:48:12
     trx_requested_lock_id: NULL
          trx_wait_started: NULL
                trx_weight: 3
       trx_mysql_thread_id: 29
                 trx_query: NULL
       trx_operation_state: NULL
         trx_tables_in_use: 0
         trx_tables_locked: 1
          trx_lock_structs: 2
     trx_lock_memory_bytes: 1128
           trx_rows_locked: 1
         trx_rows_modified: 1
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
 trx_adaptive_hash_latched: 0
 trx_adaptive_hash_timeout: 0
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
       trx_schedule_weight: NULL
*************************** 3. row ***************************
                    trx_id: 3031346
                 trx_state: RUNNING
               trx_started: 2024-01-02 07:44:07
     trx_requested_lock_id: NULL
          trx_wait_started: NULL
                trx_weight: 3
       trx_mysql_thread_id: 13
                 trx_query: NULL
       trx_operation_state: NULL
         trx_tables_in_use: 0
         trx_tables_locked: 1
          trx_lock_structs: 2
     trx_lock_memory_bytes: 1128
           trx_rows_locked: 1
         trx_rows_modified: 1
   trx_concurrency_tickets: 0
       trx_isolation_level: REPEATABLE READ
         trx_unique_checks: 1
    trx_foreign_key_checks: 1
trx_last_foreign_key_error: NULL
 trx_adaptive_hash_latched: 0
 trx_adaptive_hash_timeout: 0
          trx_is_read_only: 0
trx_autocommit_non_locking: 0
       trx_schedule_weight: NULL
3 rows in set (0.00 sec)

@davidpan
Copy link
Author

davidpan commented Jan 2, 2024

A test job that can be used to reproduce the problem. Press Ctrl-C when prompted.

class CtrlCTestJob < ApplicationJob
  self.queue_adapter = :solid_queue
  queue_as :chrome_single
  limits_concurrency to: 1, key: ->(i) { i }, duration: 5.minutes

  def perform(i)
    # Do something later
    pp "start #{i}...."
    options = Selenium::WebDriver::Chrome::Options.new
    options.add_argument('--headless')
    web_driver = Selenium::WebDriver.for(:chrome, options:)
    web_driver.manage.timeouts.implicit_wait = 20
    web_driver.get "https://www.bing.com"
    web_driver.manage.window.resize_to(1024, 1024)
    pp web_driver.title
    pp "press Ctrl-C "
    sleep(10)
    web_driver.close
    web_driver.quit
  end
end

log:

[SolidQueue] Pruning dead process 82 - {}
[SolidQueue] Starting Dispatcher(pid=10566, hostname=Desktop, metadata={:polling_interval=>1, :batch_size=>500})
[SolidQueue] Starting Worker(pid=10568, hostname=Desktop, metadata={:polling_interval=>1, :queues=>"chrome_single", :thread_pool_size=>1})
[SolidQueue] Error deregistering process 82 - {}
[SolidQueue] Claimed 1 jobs
"start 2...."
"Bing"
"press Ctrl-C "
^C[SolidQueue] Terminating gracefully...
[SolidQueue] Terminating immediately...
[SolidQueue] Error deregistering process 103 - {}
bin/rails aborted!
ActiveRecord::LockWaitTimeout: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction (ActiveRecord::LockWaitTimeout)


Caused by:
Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction (Mysql2::Error::TimeoutError)

Tasks: TOP => solid_queue:start
(See full trace by running task with --trace)

@rosa
Copy link
Member

rosa commented Jan 2, 2024

Thank you! That's very helpful, I'll dig into these.

@jmarchello
Copy link

jmarchello commented Jan 8, 2024

@rosa I too am getting the "Error deregistering process" error. This has also resulted in unique constraint errors on claimed_executions when trying to start solid_queue. I still actually have the lingering processes in my database so I thought I'd do some poking around. When trying to destroy a process I get the following:

irb(main):001> SolidQueue::Process.first.destroy!
  SolidQueue::Process Load (0.9ms)  SELECT "solid_queue_processes".* FROM "solid_queue_processes" ORDER BY "solid_queue_processes"."id" ASC LIMIT $1  [["LIMIT", 1]]
  TRANSACTION (0.1ms)  BEGIN
  SolidQueue::Process Load (0.3ms)  SELECT "solid_queue_processes".* FROM "solid_queue_processes" WHERE "solid_queue_processes"."supervisor_id" = $1  [["supervisor_id", 19]]
  SolidQueue::Process Load (0.2ms)  SELECT "solid_queue_processes".* FROM "solid_queue_processes" WHERE "solid_queue_processes"."supervisor_id" = $1  [["supervisor_id", 19]]
  SolidQueue::Process Load (0.2ms)  SELECT "solid_queue_processes".* FROM "solid_queue_processes" WHERE "solid_queue_processes"."supervisor_id" = $1  [["supervisor_id", 19]]

  [... several hundred lines of this ....]

  SolidQueue::Process Load (0.1ms)  SELECT "solid_queue_processes".* FROM "solid_queue_processes" WHERE "solid_queue_processes"."supervisor_id" = $1  [["supervisor_id", 19]]
  SolidQueue::Process Load (0.1ms)  SELECT "solid_queue_processes".* FROM "solid_queue_processes" WHERE "solid_queue_processes"."supervisor_id" = $1  [["supervisor_id", 19]]
  TRANSACTION (0.1ms)  ROLLBACK
/Users/jmarchello/.rbenv/versions/3.3.0/lib/ruby/gems/3.3.0/gems/activerecord-7.1.2/lib/active_record/model_schema.rb:441:in `attribute_types': stack level too deep (SystemStackError)

This in my local machine, a MacBook Pro. Using Postgresql 14

@rosa
Copy link
Member

rosa commented Jan 8, 2024

Oh, thank you so much @jmarchello! I think I know the problem, I'll try to work on a fix tomorrow, I didn't have time last week in the end. Thanks all for your patience 🙏

@jmarchello
Copy link

jmarchello commented Jan 8, 2024

@rosa I may have realized that my particular issue was entirely my fault :). We use UUIDs for our ids so I had edited the initial solid_queue migration to use UUIDs, but I missed the supervisor_id on processes, and process_id on claimed executions. I just thought I'd let you know in case what I sent above is not relevant to the original issue. Thanks for all your work on this!

@rosa
Copy link
Member

rosa commented Jan 9, 2024

Ahhhh! Thank you! 🙏 The infinite loop indeed didn't seem related to the error I think I have here (a race condition with the supervised processes and the supervisor trying to deregister) but it was interesting nonetheless! I was going to ask whether you perhaps had somehow a supervisor supervising itself 😅

@rosa
Copy link
Member

rosa commented Jan 9, 2024

@davidpan I finally could reproduce your issue, in my case I had to set

config.solid_queue.shutdown_timeout = 2.seconds

I'll work on a fix!

@rosa
Copy link
Member

rosa commented Jan 10, 2024

@davidpan, could you try #119 and see if it fixes your issue?

@davidpan
Copy link
Author

Comment the following previously added.

#config.solid_queue.shutdown_timeout = 60.seconds

Modify gem source to github:

gem 'solid_queue',:github => 'basecamp/solid_queue'

execute bundle install

Fetching https://github.com/basecamp/solid_queue.git
Fetching gem metadata from https://rubygems.org/........
Resolving dependencies...
Using solid_queue 0.2.0 (was 0.1.2) from https://github.com/basecamp/solid_queue.git (at main@3c70451)
Bundle complete! 40 Gemfile dependencies, 133 gems now installed.
Use `bundle info [gemname]` to see where a bundled gem is installed.

Running the test several times, pressing Ctrl-C before web_driver.get accesses the web address has a higher probability of success, and if you press Ctrl-C after accessing the web page, it has a higher probability of failure.

A sample error log is shown below:

[SolidQueue] Claimed 1 jobs
"start"
^C[SolidQueue] Terminating gracefully...
[SolidQueue] Terminating immediately...
[SolidQueue] Error deregistering process 176 - {}
bin/rails aborted!
ActiveRecord::LockWaitTimeout: Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction (ActiveRecord::LockWaitTimeout)


Caused by:
Mysql2::Error::TimeoutError: Lock wait timeout exceeded; try restarting transaction (Mysql2::Error::TimeoutError)

Tasks: TOP => solid_queue:start
(See full trace by running task with --trace)

@rosa
Copy link
Member

rosa commented Jan 11, 2024

Thanks @davidpan! Could you try doing this?

gem 'solid_queue',:github => 'basecamp/solid_queue', :branch => 'fix-race-condition-on-deregistration'

Looks like you're still running the code without the fix in these logs above.

@davidpan
Copy link
Author

@rosa Sorry, didn't realize it hadn't been merged yet.
Retested to confirm it's fixed, thanks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants