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

Fix flakey async test thread error #849

Open
bensheldon opened this issue Feb 16, 2023 · 8 comments
Open

Fix flakey async test thread error #849

bensheldon opened this issue Feb 16, 2023 · 8 comments

Comments

@bensheldon
Copy link
Owner

Failures:

  1) ActiveJob::QueueAdapters::GoodJobAdapter#initialize when in development environment runs async
     Failure/Error: expect(THREAD_ERRORS).to be_empty
       expected `[["GoodJob::Scheduler(queues=* max_threads=5)-worker-1", #<ActiveRecord::ConnectionNotEstablished: connection is closed>, ["/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/rack-mini-profiler-3.0.0/lib/patches/db/pg.rb:110:in `exec'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/rack-mini-profiler-3.0.0/lib/patches/db/pg.rb:110:in `async_exec'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/postgresql/database_statements.rb:19:in `block (2 levels) in query'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/postgresql/database_statements.rb:18:in `block in query'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/abstract_adapter.rb:696:in `block (2 levels) in log'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/abstract_adapter.rb:695:in `block in log'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/notifications/instrumenter.rb:24:in `instrument'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/abstract_adapter.rb:687:in `log'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/postgresql/database_statements.rb:17:in `query'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/abstract/database_statements.rb:103:in `query_values'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/abstract/schema_statements.rb:45:in `data_source_exists?'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/schema_cache.rb:92:in `data_source_exists?'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/type_caster/connection.rb:19:in `type_for_attribute'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/arel/table.rb:108:in `type_for_attribute'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/table_metadata.rb:18:in `type'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predicate_builder.rb:63:in `build'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predicate_builder.rb:58:in `[]'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predicate_builder.rb:131:in `block in expand_from_hash'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predicate_builder.rb:84:in `each'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predicate_builder.rb:84:in `flat_map'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predicate_builder.rb:84:in `expand_from_hash'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predicate_builder.rb:87:in `block in expand_from_hash'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predicate_builder.rb:84:in `each'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predicate_builder.rb:84:in `flat_map'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predicate_builder.rb:84:in `expand_from_hash'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predicate_builder.rb:29:in `build_from_hash'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/query_methods.rb:1093:in `build_where_clause'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/query_methods.rb:645:in `where!'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/query_methods.rb:640:in `where'", "/home/runner/work/good_job/good_job/app/models/good_job/lockable.rb:101:in `block (2 levels) in <module:Lockable>'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation.rb:411:in `instance_exec'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation.rb:411:in `block in _exec_scope'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation.rb:804:in `_scoping'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation.rb:411:in `_exec_scope'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/scoping/named.rb:176:in `block in scope'", "/home/runner/work/good_job/good_job/app/models/good_job/execution.rb:268:in `next_scheduled_at'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/delegation.rb:67:in `block in next_scheduled_at'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation.rb:406:in `block in scoping'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation.rb:804:in `_scoping'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation.rb:406:in `scoping'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/delegation.rb:67:in `next_scheduled_at'", "/home/runner/work/good_job/good_job/lib/good_job/job_performer.rb:65:in `next_at'", "/home/runner/work/good_job/good_job/lib/good_job/scheduler.rb:233:in `block (2 levels) in warm_cache'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/execution_wrapper.rb:91:in `wrap'", "/home/runner/work/good_job/good_job/lib/good_job/scheduler.rb:232:in `block in warm_cache'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.0/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.0/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `block in synchronize'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.0/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.0/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.0/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:[22](https://github.com/bensheldon/good_job/actions/runs/4187985898/jobs/7258540796#step:6:23):in `execute'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.0/lib/concurrent-ruby/concurrent/ivar.rb:170:in `safe_execute'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.0/lib/concurrent-ruby/concurrent/future.rb:55:in `block in execute'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.0/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:352:in `run_task'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.0/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:343:in `block (3 levels) in create_worker'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.0/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `loop'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.0/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `block (2 levels) in create_worker'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.0/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `catch'", "/home/runner/work/good_job/good_job/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.0/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `block in create_worker'"]]].empty?` to be truthy, got false
     # ./spec/support/reset_good_job.rb:[25](https://github.com/bensheldon/good_job/actions/runs/4187985898/jobs/7258540796#step:6:26):in `block (2 levels) in <top (required)>'
     # ./spec/support/reset_rails_queue_adapter.rb:12:in `block (2 levels) in <top (required)>'
     # ./spec/support/reset_good_job.rb:19:in `block (2 levels) in <top (required)>'
     # ./spec/support/database_cleaner.rb:12:in `block (2 levels) in <top (required)>'

Finished in 5 minutes [27](https://github.com/bensheldon/good_job/actions/runs/4187985898/jobs/7258540796#step:6:28) seconds (files took 3.04 seconds to load)
398 examples, 1 failure
@bensheldon
Copy link
Owner Author

Same same:

  1) GoodJob::Adapter#execute_async? when execution mode async_all returns true
     Failure/Error: expect(THREAD_ERRORS).to be_empty
       expected `[["GoodJob::Scheduler(queues=* max_threads=5)-worker-1", #<ActiveRecord::ConnectionNotEstablished: connection is closed>, ["/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/rack-mini-profiler-3.0.0/lib/patches/db/pg.rb:110:in `exec'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/rack-mini-profiler-3.0.0/lib/patches/db/pg.rb:110:in `async_exec'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/postgresql/database_statements.rb:19:in `block (2 levels) in query'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/dependencies/interlock.rb:48:in `block in permit_concurrent_loads'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/concurrency/share_lock.rb:187:in `yield_shares'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/dependencies/interlock.rb:47:in `permit_concurrent_loads'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/postgresql/database_statements.rb:18:in `block in query'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/abstract_adapter.rb:696:in `block (2 levels) in log'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:26:in `block (2 levels) in synchronize'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `handle_interrupt'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:25:in `block in synchronize'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `handle_interrupt'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/concurrency/load_interlock_aware_monitor.rb:21:in `synchronize'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/abstract_adapter.rb:695:in `block in log'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/notifications/instrumenter.rb:24:in `instrument'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/abstract_adapter.rb:687:in `log'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/postgresql/database_statements.rb:17:in `query'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/abstract/database_statements.rb:103:in `query_values'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/abstract/schema_statements.rb:45:in `data_source_exists?'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/connection_adapters/schema_cache.rb:92:in `data_source_exists?'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/type_caster/connection.rb:19:in `type_for_attribute'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/arel/table.rb:108:in `type_for_attribute'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/table_metadata.rb:18:in `type'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predicate_builder.rb:63:in `build'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predicate_builder.rb:58:in `[]'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predicate_builder.rb:131:in `block in expand_from_hash'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predicate_builder.rb:84:in `each'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/predic..._where_clause'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/query_methods.rb:645:in `where!'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/query_methods.rb:640:in `where'", "/home/runner/work/good_job/good_job/app/models/good_job/lockable.rb:101:in `block (2 levels) in <module:Lockable>'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation.rb:411:in `instance_exec'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation.rb:411:in `block in _exec_scope'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation.rb:804:in `_scoping'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation.rb:411:in `_exec_scope'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/scoping/named.rb:176:in `block in scope'", "/home/runner/work/good_job/good_job/app/models/good_job/execution.rb:268:in `next_scheduled_at'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/delegation.rb:67:in `block in next_scheduled_at'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation.rb:406:in `block in scoping'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation.rb:804:in `_scoping'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation.rb:406:in `scoping'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activerecord-6.1.7.2/lib/active_record/relation/delegation.rb:67:in `next_scheduled_at'", "/home/runner/work/good_job/good_job/lib/good_job/job_performer.rb:65:in `next_at'", "/home/runner/work/good_job/good_job/lib/good_job/scheduler.rb:235:in `block (2 levels) in warm_cache'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/activesupport-6.1.7.2/lib/active_support/execution_wrapper.rb:91:in `wrap'", "/home/runner/work/good_job/good_job/lib/good_job/scheduler.rb:234:in `block in warm_cache'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `block in synchronize'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22:in `execute'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/ivar.rb:170:in `safe_execute'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/future.rb:55:in `block in execute'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:352:in `run_task'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:343:in `block (3 levels) in create_worker'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `loop'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `block (2 levels) in create_worker'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `catch'", "/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/2.7.0/gems/concurrent-ruby-1.2.2/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `block in create_worker'"]]].empty?` to be truthy, got false
     # ./spec/support/reset_good_job.rb:35:in `block (2 levels) in <top (required)>'
     # ./spec/support/reset_rails_queue_adapter.rb:12:in `block (2 levels) in <top (required)>'
     # ./spec/support/reset_good_job.rb:19:in `block (2 levels) in <top (required)>'
     # ./spec/support/database_cleaner.rb:12:in `block (2 levels) in <top (required)>'

Finished in 2 minutes 28.7 seconds (files took 3.67 seconds to load)
392 examples, 1 failure

Failed examples:

rspec ./spec/lib/good_job/adapter_spec.rb:168 # GoodJob::Adapter#execute_async? when execution mode async_all returns true

Randomized with seed 1321

@bensheldon
Copy link
Owner Author

1) GoodJob.restart does nothing when there are no capsule instances
     Failure/Error: expect(GoodJob::Capsule.instances).to be_empty
       expected `[#<GoodJob::Capsule:0x2d7e6c8c @mutex=#<Thread::Mutex:0x76b35c38>, @configuration=#<GoodJob::Configuration:0xced7e4a @env={"GITHUB_WORKSPACE"=>"/home/runner/work/good_job/good_job", "PGHOST"=>"localhost", "CHROMEWEBDRIVER"=>"/usr/local/share/chrome_driver", "RUNNER_USER"=>"runner", "SWIFT_PATH"=>"/usr/share/swift/usr/bin", "ANDROID_SDK_ROOT"=>"/usr/local/lib/android/sdk", "JAVA_HOME"=>"/usr/lib/jvm/temurin-11-jdk-amd64", "ANDROID_NDK_HOME"=>"/usr/local/lib/android/sdk/ndk/25.2.9519653", "APPRAISAL_INITIALIZED"=>"1", "GITHUB_WORKFLOW"=>"Test", "STATS_RDCL"=>"true", "ANDROID_NDK_ROOT"=>"/usr/local/lib/android/sdk/ndk/25.2.9519653", "PIPX_BIN_DIR"=>"/opt/pipx_bin", "GITHUB_ACTIONS"=>"true", "JAVA_HOME_17_X64"=>"/usr/lib/jvm/temurin-17-jdk-amd64", "GITHUB_ENV"=>"/home/runner/work/_temp/_runner_file_commands/set_env_c23d81ae-061c-4387-a9c3-3bc5bf50fa44", "BUNDLE_RETRY"=>"3", "ANDROID_NDK"=>"/usr/local/lib/android/sdk/ndk/25.2.9519653", "GITHUB_SHA"=>"15ada3d78693ea39cab2fbc842699c9bd315bf25", "RUNNER_OS"=>"Linux", "GITHUB_API_URL"=>"https://api.github.com/", "RAILS_LOG_TO_STDOUT"=>"false", "JAVA_HOME_8_X64"=>"/usr/lib/jvm/temurin-8-jdk-amd64", "PERFLOG_LOCATION_SETTING"=>"RUNNER_PERFLOG", "CHROME_BIN"=>"/usr/bin/google-chrome", "GITHUB_RETENTION_DAYS"=>"90", "ImageVersion"=>"20230313.1", "BUNDLE_GEMFILE"=>"/home/runner/work/good_job/good_job/gemfiles/rails_6.1.gemfile", "GITHUB_RUN_ATTEMPT"=>"1", "GRADLE_HOME"=>"/usr/share/gradle-8.0.2", "GITHUB_OUTPUT"=>"/home/runner/work/_temp/_runner_file_commands/set_output_c23d81ae-061c-4387-a9c3-3bc5bf50fa44", "GITHUB_RUN_ID"=>"4441156798", "CONDA"=>"/usr/share/miniconda", "STATS_NM"=>"true", "EDGEWEBDRIVER"=>"/usr/local/share/edge_driver", "GITHUB_HEAD_REF"=>"json_executions", "GOROOT_1_18_X64"=>"/opt/hostedtoolcache/go/1.18.10/x64", "DEBIAN_FRONTEND"=>"noninteractive", "LANG"=>"C.UTF-8", "JOURNAL_STREAM"=>"8:17121", "ANDROID_HOME"=>"/usr/local/lib/android/sdk", "GITHUB_PATH"=>"/home/runner/work/_temp/_runner_file_commands/add_path_c23d81ae-061c-4387-a9c3-3bc5bf50fa44", "GITHUB_REF_TYPE"=>"branch", "GITHUB_ACTOR"=>"bensheldon", "XDG_CONFIG_HOME"=>"/home/runner/.config", "POWERSHELL_DISTRIBUTION_CHANNEL"=>"GitHub-Actions-ubuntu22", "RUNNER_ARCH"=>"X64", "GITHUB_REF"=>"refs/pull/894/merge", "ImageOS"=>"ubuntu22", "GITHUB_EVENT_NAME"=>"pull_request", "PATH"=>"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/jruby/2.6.0/bin:/home/runner/.rubies/jruby-9.3.10.0/bin:/opt/hostedtoolcache/chromium/latest/x64:/home/runner/.local/bin:/opt/pipx_bin:/home/runner/.cargo/bin:/home/runner/.config/composer/vendor/bin:/usr/local/.ghcup/bin:/home/runner/.dotnet/tools:/snap/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games", "CI"=>"true", "RUNNER_PERFLOG"=>"/home/runner/perflog", "GITHUB_WORKFLOW_SHA"=>"15ada3d78693ea39cab2fbc842699c9bd315bf25", "SELENIUM_JAR_PATH"=>"/usr/share/java/selenium-server.jar", "GITHUB_TRIGGERING_ACTOR"=>"bensheldon", "HOMEBREW_CLEANUP_PERIODIC_FULL_DAYS"=>"3650", "GITHUB_REPOSITORY_ID"=>"242765280", "AZURE_EXTENSION_DIR"=>"/opt/az/azcliextensions", "ANT_HOME"=>"/usr/share/ant", "GITHUB_REPOSITORY"=>"bensheldon/good_job", "GITHUB_BASE_REF"=>"main", "SGX_AESM_ADDR"=>"1", "XDG_RUNTIME_DIR"=>"/run/user/1001", "RAILS_ENV"=>"test", "GITHUB_RUN_NUMBER"=>"1822", "BUNDLE_JOBS"=>"4", "GITHUB_ACTION"=>"__run_6", "AGENT_TOOLSDIRECTORY"=>"/opt/hostedtoolcache", "GITHUB_REF_PROTECTED"=>"false", "PGUSER"=>"good_job", "GHCUP_INSTALL_BASE_PREFIX"=>"/usr/local", "BUNDLE_PATH"=>"vendor/bundle", "LEIN_HOME"=>"/usr/local/lib/lein", "GOROOT_1_19_X64"=>"/opt/hostedtoolcache/go/1.19.7/x64", "ANDROID_NDK_LATEST_HOME"=>"/usr/local/lib/android/sdk/ndk/25.2.9519653", "HOME"=>"/home/runner", "RUNNER_TRACKING_ID"=>"github_4e938db1-7f9f-4bdd-8a4f-ccfb58d1a436", "GOROOT_1_17_X64"=>"/opt/hostedtoolcache/go/1.17.13/x64", "NVM_DIR"=>"/home/runner/.nvm", "GITHUB_EVENT_PATH"=>"/home/runner/work/_temp/_github_workflow/event.json", "GITHUB_SERVER_URL"=>"https://github.com/", "ACCEPT_EULA"=>"Y", "JAVA_HOME_11_X64"=>"/usr/lib/jvm/temurin-11-jdk-amd64", "GITHUB_GRAPHQL_URL"=>"https://api.github.com/graphql", "RUNNER_TEMP"=>"/home/runner/work/_temp", "GRAALVM_11_ROOT"=>"/usr/local/graalvm/graalvm-ce-java11-22.3.1", "GECKOWEBDRIVER"=>"/usr/local/share/gecko_driver", "USER"=>"runner", "GITHUB_ACTOR_ID"=>"47554", "DOTNET_NOLOGO"=>"1", "GITHUB_ACTION_REF"=>"", "BUNDLE_WITHOUT"=>"lint", "GITHUB_ACTION_REPOSITORY"=>"", "GITHUB_REPOSITORY_OWNER"=>"bensheldon", "LEIN_JAR"=>"/usr/local/lib/lein/self-installs/leiningen-2.10.0-standalone.jar", "GITHUB_REF_NAME"=>"894/merge", "BOOTSTRAP_HASKELL_NONINTERACTIVE"=>"1", "DOTNET_SKIP_FIRST_TIME_EXPERIENCE"=>"1", "SYSTEMD_EXEC_PID"=>"680", "HOMEBREW_NO_AUTO_UPDATE"=>"1", "PIPX_HOME"=>"/opt/pipx", "GITHUB_STATE"=>"/home/runner/work/_temp/_runner_file_commands/save_state_c23d81ae-061c-4387-a9c3-3bc5bf50fa44", "VCPKG_INSTALLATION_ROOT"=>"/usr/local/share/vcpkg", "PWD"=>"/home/runner/work/good_job/good_job", "GITHUB_WORKFLOW_REF"=>"bensheldon/good_job/.github/workflows/test.yml@refs/pull/894/merge", "GITHUB_REPOSITORY_OWNER_ID"=>"47554", "SHLVL"=>"1", "RUNNER_NAME"=>"GitHub Actions 31", "DEPLOYMENT_BASEPATH"=>"/opt/runner", "RUNNER_TOOL_CACHE"=>"/opt/hostedtoolcache", "GITHUB_JOB"=>"test", "RUNNER_WORKSPACE"=>"/home/runner/work/good_job", "GITHUB_STEP_SUMMARY"=>"/home/runner/work/_temp/_runner_file_commands/step_summary_c23d81ae-061c-4387-a9c3-3bc5bf50fa44", "DOTNET_MULTILEVEL_LOOKUP"=>"0", "_"=>"/home/runner/.rubies/jruby-9.3.10.0/bin/bundle", "GOROOT_1_20_X64"=>"/opt/hostedtoolcache/go/1.20.2/x64", "INVOCATION_ID"=>"a26a7e7a3e0347c89835875d9d87f756", "BUNDLER_ORIG_BUNDLE_BIN_PATH"=>"BUNDLER_ENVIRONMENT_PRESERVER_INTENTIONALLY_NIL", "BUNDLER_ORIG_BUNDLE_GEMFILE"=>"/home/runner/work/good_job/good_job/gemfiles/rails_6.1.gemfile", "BUNDLER_ORIG_BUNDLER_VERSION"=>"BUNDLER_ENVIRONMENT_PRESERVER_INTENTIONALLY_NIL", "BUNDLER_ORIG_BUNDLER_SETUP"=>"BUNDLER_ENVIRONMENT_PRESERVER_INTENTIONALLY_NIL", "BUNDLER_ORIG_GEM_HOME"=>"BUNDLER_ENVIRONMENT_PRESERVER_INTENTIONALLY_NIL", "BUNDLER_ORIG_GEM_PATH"=>"BUNDLER_ENVIRONMENT_PRESERVER_INTENTIONALLY_NIL", "BUNDLER_ORIG_MANPATH"=>"BUNDLER_ENVIRONMENT_PRESERVER_INTENTIONALLY_NIL", "BUNDLER_ORIG_PATH"=>"/home/runner/.rubies/jruby-9.3.10.0/bin:/opt/hostedtoolcache/chromium/latest/x64:/home/runner/.local/bin:/opt/pipx_bin:/home/runner/.cargo/bin:/home/runner/.config/composer/vendor/bin:/usr/local/.ghcup/bin:/home/runner/.dotnet/tools:/snap/bin:/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin:/sbin:/bin:/usr/games:/usr/local/games:/snap/bin", "BUNDLER_ORIG_RB_USER_INSTALL"=>"BUNDLER_ENVIRONMENT_PRESERVER_INTENTIONALLY_NIL", "BUNDLER_ORIG_RUBYLIB"=>"BUNDLER_ENVIRONMENT_PRESERVER_INTENTIONALLY_NIL", "BUNDLER_ORIG_RUBYOPT"=>"BUNDLER_ENVIRONMENT_PRESERVER_INTENTIONALLY_NIL", "BUNDLE_BIN_PATH"=>"/home/runner/.rubies/jruby-9.3.10.0/lib/ruby/gems/shared/gems/bundler-2.4.7/exe/bundle", "BUNDLER_VERSION"=>"2.4.7", "RUBYOPT"=>"-r/home/runner/.rubies/jruby-9.3.10.0/lib/ruby/gems/shared/gems/bundler-2.4.7/lib/bundler/setup", "RUBYLIB"=>"/home/runner/.rubies/jruby-9.3.10.0/lib/ruby/gems/shared/gems/bundler-2.4.7/lib", "GEM_PATH"=>"", "GEM_HOME"=>"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/jruby/2.6.0", "MANPATH"=>"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/jruby/2.6.0/gems/kramdown-2.4.0/man:"}, @options={}>, @running=false, @autostart=true>].empty?` to be truthy, got false
     # ./spec/lib/good_job_spec.rb:30:in `block in <main>'
     # ./spec/support/reset_rails_queue_adapter.rb:12:in `block in <main>'
     # ./spec/support/reset_good_job.rb:19:in `block in <main>'
     # ./spec/support/database_cleaner.rb:12:in `block in <main>'

Finished in 3 minutes 19.7 seconds (files took 12.17 seconds to load)
392 examples, 1 failure

Failed examples:

rspec ./spec/lib/good_job_spec.rb:29 # GoodJob.restart does nothing when there are no capsule instances

Randomized with seed 62095

@bensheldon
Copy link
Owner Author

From poking at this in #915:

  • TIL stubbed objects are still active in RSpec after blocks
  • One theory was the problem was that threads were lingering beyond the boundaries of their test. But after adding more logging, it seemed like the scheduler and its threads were being created in the same test reporting a thread error.
  • Another theory was that ActiveRecord::Tasks::DatabaseTasks.truncate_all was doing something to disrupt a database connection, and then it would be reused at some random point in time later and be in a bad state. (e.g. Only remove connection for an existing pool if the config is different rails/rails#45450). That didn't seem to be the problem though.

@dmolesUC
Copy link

dmolesUC commented Apr 11, 2023

So, I'm not sure if this the same thing or not, but:

I have a suite of tests using shared examples to test various combinations of invalid attributes posted to an endpoint. If I write really minimal, fast examples like:

it 'returns an invalid response' do
  post holdings_tasks_url, params: { holdings_task: invalid_attributes }
  expect(response).not_to be_successful
end

— then each test passes individually, but in a suite, all tests after the first one or two fail with PG::ConnectionBad: connection is closed being raised from DatabaseCleaner::ActiveRecord::ConnectionWrapper::PostgreSQLAdapter#truncate_tables.

When I put some breakpoints in trying to figure out where the connection was being closed:

  1. my best guess is it's GoodJob::Notifier#with_connection
  2. the suite passes.

Likewise, if I write a more complicated example like:

it 'does not create a task or schedule a job' do
  expect(GoodJob::Batch).not_to receive(:enqueue)

  job_classes.each do |jc|
    expect(jc).not_to receive(:perform)
  end

  expect do
    post holdings_tasks_url, params: { holdings_task: invalid_attributes }
  end.not_to change(HoldingsTask, :count)
  expect(response).not_to be_successful

  expect(GoodJob::BatchRecord.exists?).to eq(false)
end

— which takes, like, 1-2 seconds to run — the suite passes.

My hypothesis is that I'm seeing something like:

  • success (slow examples):
    1. first example starts
    2. GoodJob::Notifier#with_connection starts
    3. GoodJob::Notifier#with_connection finishes, closing connection
    4. first example ends
    5. DatabaseCleaner.clean is called, and gets a new connection
    6. second example starts
    7. (etc.)
  • failure (fast examples):
    1. first example starts
    2. GoodJob::Notifier#with_connection starts
    3. first example ends
    4. DatabaseCleaner.clean is called, and gets a new connection
    5. GoodJob::Notifier#with_connection finishes, closing connection
    6. second example starts
    7. GoodJob::Notifier#with_connection starts
    8. second example ends
    9. DatabaseCleaner.clean is called, and somehow gets the same connection GoodJob::Notifier#with_connection (as triggered from the previous example) just closed

— but I don't really know.

(Anyway, my workaround is just to put all my assertions in one fat, slow example.)

@dmolesUC
Copy link

(Note BTW that no jobs are run in the course of these tests -- in fact we're asserting that they're not. 🙂)

@dmolesUC
Copy link

As a more general workaround, this seems to work:

after do
  GoodJob::Notifier.instances.each(&:shutdown)
end

@bensheldon
Copy link
Owner Author

@dmolesUC glad you found a workaround 👍 you can also use GoodJob.shutdown to shut them down too.

Are you intentionally running the adapter in async execution mode? By default GoodJob uses inline execution which shouldn't spin up a Notifier instance.

I really appreciate your detailed hypothesis of what's happening. That's super helpful! I admit I don't quite understand the complete lifecycle of the Active Record connections and pool 😅

@dmolesUC
Copy link

@bensheldon I am using async mode intentionally for this particular group of tests -- wanting to make sure we haven't accidentally baked in any assumptions about things happening serially or in a certain thread. (The price is a lot of shenanigans involving callbacks and rescue handlers and Concurrent::CountDownLatch, but they're mostly hidden in one file under spec/support, and it's better than trying to diagnose problems later on a running server.)

The workaround proved not to be reliable, unfortunately, but I think I finally pinned down my underlying problem, and found a different workaround: DatabaseCleaner/database_cleaner-active_record#86

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

No branches or pull requests

2 participants