search

bensheldon / good_job

Multithreaded, Postgres-based, Active Job backend for Ruby on Rails.
https://goodjob-demo.herokuapp.com/
MIT License
2.69k stars 200 forks source link

Fix flakey async test thread error #849

Open bensheldon opened 1 year ago

bensheldon commented 1 year ago 
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 commented 1 year ago

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 commented 1 year ago 
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 commented 1 year ago

From poking at this in #915:

dmolesUC commented 1 year ago

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:

— but I don't really know.

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

dmolesUC commented 1 year ago

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

dmolesUC commented 1 year ago

As a more general workaround, this seems to work:

after do
  GoodJob::Notifier.instances.each(&:shutdown)
end
bensheldon commented 1 year ago

@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 commented 1 year ago

@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: https://github.com/DatabaseCleaner/database_cleaner-active_record/issues/86