good_job: Experiencing various database exceptions with Rails 7.1
I’m running Rails 7.1 from HEAD on a new app and have run into several strange exceptions coming from somewhere in the GoodJob / Rails / pg gem stack.
As you’ll see, the errors vary. I’m suspicious of a DB connection being accidentally shared between threads, but am not really sure if it’s in GoodJob, ActiveRecord, or even the pg gem. It appears that Rails 7.1 made some optimizations to the threading/locking in ActiveRecord back a couple (few?) months ago, but I can’t say for sure if that’s related.
The errors all seem to happen right when GoodJob is first loading and making its first queries. If things load without error, the process remains stable. Further, depending on the initial error, the process may stabilize afterward. For other errors, something gets corrupted inside ActiveRecord (schema-type information it seems), and subsequent queries continue to error. In one instance, Ruby itself crashed with a segfault.
I’m posting this here to start, but I’m not fully sure if the issue lies within GoodJob or elsewhere.
Context
I’m running GoodJob in a separate process, via bin/good_job, which is where these show up. I do not recall seeing errors from inside the Rails server process (when scheduling GoodJob jobs or otherwise). I have not tried async or any other modes to compare.
good_job 3.7.4
rails 7.1.0.alpha from main as of Jan 14, but examples below vary from today back to Jan 1
pg 1.4.5
ruby 3.1.3, on macOS 12.6.2
I also tried 2-3 earlier versions of pg and forced a full recompile of 1.4.5. And, I also tried without bootsnap, but that made no difference.
The errors
As a general rule, I silence ActiveRecord queries in development, so many of these backtraces don’t include the queries. I apologize. I’ll start with the newest, since it does show them.
(Numbering comes from my own notes; please excuse skipped numbers.)
# 6 - map_types! - This one seems to be the most common.
13:07:36 goodjob.1 | [GoodJob] [16210] GoodJob 3.7.4 started scheduler with queues=* max_threads=5.
13:07:36 goodjob.1 | (0.8ms) SET application_name = 'GoodJob::Notifier'
13:07:36 goodjob.1 | (0.1ms) LISTEN good_job
13:07:36 goodjob.1 | [GoodJob] Notifier subscribed with LISTEN
13:07:36 goodjob.1 | GoodJob::Execution Pluck (1.9ms) SELECT "good_jobs"."scheduled_at", "good_jobs"."created_at" FROM "good_jobs" LEFT JOIN pg_locks ON pg_locks.locktype = 'advisory' AND pg_locks.objsubid = 1 AND pg_locks.classid = ('x' || substr(md5('good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(32)::int AND pg_locks.objid = (('x' || substr(md5('good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(64) << 32)::bit(32)::int WHERE "pg_locks"."locktype" IS NULL AND "good_jobs"."finished_at" IS NULL AND (scheduled_at > '2023-01-14 20:07:36.300494' OR "good_jobs"."scheduled_at" IS NULL AND (created_at > '2023-01-14 20:07:36.300494')) ORDER BY COALESCE(scheduled_at, created_at) ASC LIMIT $1 [["LIMIT", 10000]]
13:07:36 goodjob.1 | (0.1ms) UNLISTEN *
13:07:36 goodjob.1 | [GoodJob] Notifier unsubscribed with UNLISTEN
13:07:36 goodjob.1 | [GoodJob] Notifier errored: NoMethodError: undefined method `map_types!' for nil:NilClass
13:07:36 goodjob.1 |
13:07:36 goodjob.1 | conn.async_exec(sql).map_types!(@type_map_for_results).values
13:07:36 goodjob.1 | ^^^^^^^^^^^
13:07:36 goodjob.1 | ["~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb:18:in `block (2 levels) in query'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:989:in `block in with_raw_connection'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activesupport/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:961:in `with_raw_connection'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb:17:in `block in query'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activesupport/lib/active_support/notifications/instrumenter.rb:58:in `instrument'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:1099:in `log'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb:16:in `query'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:99:in `query_values'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/connection_adapters/postgresql/schema_statements.rb:358:in `primary_keys'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/connection_adapters/abstract/schema_statements.rb:145:in `primary_key'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/connection_adapters/schema_cache.rb:82:in `block in primary_keys'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/connection_adapters/schema_cache.rb:80:in `fetch'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/connection_adapters/schema_cache.rb:80:in `primary_keys'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/attribute_methods/primary_key.rb:96:in `get_primary_key'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/attribute_methods/primary_key.rb:83:in `reset_primary_key'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/attribute_methods/primary_key.rb:71:in `primary_key'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/app/models/good_job/lockable.rb:224:in `_advisory_lockable_column'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation/delegation.rb:108:in `public_send'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation/delegation.rb:108:in `block in method_missing'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation.rb:895:in `_scoping'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation.rb:433:in `scoping'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation/delegation.rb:108:in `method_missing'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/app/models/good_job/lockable.rb:101:in `block (2 levels) in <module:Lockable>'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation.rb:440:in `instance_exec'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation.rb:440:in `block in _exec_scope'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation.rb:895:in `_scoping'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation.rb:440:in `_exec_scope'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/scoping/named.rb:175:in `block in scope'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation/delegation.rb:67:in `block in advisory_unlocked'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation.rb:895:in `_scoping'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation.rb:433:in `scoping'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation/delegation.rb:67:in `advisory_unlocked'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/app/models/good_job/process.rb:26:in `block in <class:Process>'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation.rb:440:in `instance_exec'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation.rb:440:in `block in _exec_scope'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation.rb:895:in `_scoping'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/relation.rb:440:in `_exec_scope'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activerecord/lib/active_record/scoping/named.rb:175:in `block in scope'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/app/models/good_job/process.rb:57:in `cleanup'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/lib/good_job/notifier/process_registration.rb:17:in `block in register_process'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/lib/good_job/assignable_connection.rb:32:in `with_connection'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/lib/good_job/notifier/process_registration.rb:16:in `register_process'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activesupport/lib/active_support/callbacks.rb:401:in `block in make_lambda'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activesupport/lib/active_support/callbacks.rb:272:in `block in simple'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activesupport/lib/active_support/callbacks.rb:600:in `block in invoke_after'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activesupport/lib/active_support/callbacks.rb:600:in `each'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activesupport/lib/active_support/callbacks.rb:600:in `invoke_after'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-9bdd29c8317a/activesupport/lib/active_support/callbacks.rb:109:in `run_callbacks'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/lib/good_job/notifier.rb:171:in `block (2 levels) in listen'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/lib/good_job/notifier.rb:215:in `with_connection'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/lib/good_job/notifier.rb:169:in `block in listen'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `block in synchronize'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `synchronize'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `synchronize'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22:in `execute'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/ivar.rb:169:in `safe_execute'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/scheduled_task.rb:298:in `process_task'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/timer_set.rb:98:in `block in ns_post_task'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:352:in `run_task'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:343:in `block (3 levels) in create_worker'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `loop'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `block (2 levels) in create_worker'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `catch'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `block in create_worker'"]
13:07:36 goodjob.1 | GoodJob::Execution Pluck (1.2ms) SELECT "good_jobs"."scheduled_at", "good_jobs"."created_at" FROM "good_jobs" LEFT JOIN pg_locks ON pg_locks.locktype = 'advisory' AND pg_locks.objsubid = 1 AND pg_locks.classid = ('x' || substr(md5('good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(32)::int AND pg_locks.objid = (('x' || substr(md5('good_jobs' || '-' || "good_jobs"."active_job_id"::text), 1, 16))::bit(64) << 32)::bit(32)::int WHERE "pg_locks"."locktype" IS NULL AND "good_jobs"."finished_at" IS NULL AND (scheduled_at < '2023-01-14 20:07:36.304257' OR "good_jobs"."scheduled_at" IS NULL) ORDER BY COALESCE(scheduled_at, created_at) ASC LIMIT $1 [["LIMIT", 5]]
13:07:36 goodjob.1 | GoodJob::Execution Load (0.8ms) SELECT "good_jobs".* FROM "good_jobs" WHERE "good_jobs"."id" IN (WITH "rows" AS MATERIALIZED ( SELECT "good_jobs"."id", "good_jobs"."active_job_id" FROM "good_jobs" WHERE "good_jobs"."finished_at" IS NULL AND ("good_jobs"."scheduled_at" <= '2023-01-14 20:07:36.314127' OR "good_jobs"."scheduled_at" IS NULL) ORDER BY priority DESC NULLS LAST, created_at ASC ) SELECT "rows"."id" FROM "rows" WHERE pg_try_advisory_lock(('x' || substr(md5('good_jobs' || '-' || "rows"."active_job_id"::text), 1, 16))::bit(64)::bigint) LIMIT $1) ORDER BY priority DESC NULLS LAST, created_at ASC [["LIMIT", 1]]
13:07:36 goodjob.1 | GoodJob::Lockable Unlock Session (0.2ms) SELECT pg_advisory_unlock_all()::text AS unlocked
# 5 - result.clear - I think I've seen this just once.
12:45:21 goodjob.1 | [GoodJob] [11795] GoodJob 3.7.4 started scheduler with queues=* max_threads=5.
12:45:21 goodjob.1 | [GoodJob] Notifier subscribed with LISTEN
12:45:21 goodjob.1 | [GoodJob] Notifier unsubscribed with UNLISTEN
12:45:21 goodjob.1 | [GoodJob] Notifier errored: NoMethodError: undefined method `clear' for nil:NilClass
12:45:21 goodjob.1 |
12:45:21 goodjob.1 | result.clear
12:45:21 goodjob.1 | ^^^^^^
12:45:21 goodjob.1 | ["~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-13783f36ad6c/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:825:in `ensure in execute_and_clear'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-13783f36ad6c/activerecord/lib/active_record/connection_adapters/postgresql_adapter.rb:825:in `execute_and_clear'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-13783f36ad6c/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb:81:in `exec_delete'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-13783f36ad6c/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:186:in `delete'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-13783f36ad6c/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:22:in `delete'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-13783f36ad6c/activerecord/lib/active_record/relation.rb:626:in `delete_all'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/app/models/good_job/process.rb:57:in `cleanup'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/lib/good_job/notifier/process_registration.rb:17:in `block in register_process'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/lib/good_job/assignable_connection.rb:32:in `with_connection'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/lib/good_job/notifier/process_registration.rb:16:in `register_process'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-13783f36ad6c/activesupport/lib/active_support/callbacks.rb:401:in `block in make_lambda'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-13783f36ad6c/activesupport/lib/active_support/callbacks.rb:272:in `block in simple'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-13783f36ad6c/activesupport/lib/active_support/callbacks.rb:600:in `block in invoke_after'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-13783f36ad6c/activesupport/lib/active_support/callbacks.rb:600:in `each'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-13783f36ad6c/activesupport/lib/active_support/callbacks.rb:600:in `invoke_after'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-13783f36ad6c/activesupport/lib/active_support/callbacks.rb:109:in `run_callbacks'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/lib/good_job/notifier.rb:171:in `block (2 levels) in listen'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/lib/good_job/notifier.rb:215:in `with_connection'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.4/lib/good_job/notifier.rb:169:in `block in listen'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `block in synchronize'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `synchronize'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `synchronize'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22:in `execute'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/ivar.rb:169:in `safe_execute'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/scheduled_task.rb:298:in `process_task'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/timer_set.rb:98:in `block in ns_post_task'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:352:in `run_task'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:343:in `block (3 levels) in create_worker'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `loop'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `block (2 levels) in create_worker'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `catch'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `block in create_worker'"]
# 4 - Length error in message type Z
12:07:16 goodjob.1 | [GoodJob] [27979] GoodJob 3.7.2 started scheduler with queues=* max_threads=5.
12:07:16 goodjob.1 | [GoodJob] Notifier subscribed with LISTEN
12:07:16 goodjob.1 | [GoodJob] Notifier unsubscribed with UNLISTEN
12:07:16 goodjob.1 | [GoodJob] Notifier errored: ActiveRecord::StatementInvalid: PG::UnableToSend: message contents do not agree with length in message type "Z"
12:07:16 goodjob.1 |
12:07:16 goodjob.1 | ["~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb:18:in `exec'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb:18:in `block (2 levels) in query'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:989:in `block in with_raw_connection'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activesupport/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:961:in `with_raw_connection'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb:17:in `block in query'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activesupport/lib/active_support/notifications/instrumenter.rb:58:in `instrument'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:1102:in `log'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb:16:in `query'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:99:in `query_values'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/connection_adapters/postgresql/schema_statements.rb:359:in `primary_keys'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/connection_adapters/abstract/schema_statements.rb:145:in `primary_key'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/connection_adapters/schema_cache.rb:82:in `block in primary_keys'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/connection_adapters/schema_cache.rb:80:in `fetch'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/connection_adapters/schema_cache.rb:80:in `primary_keys'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/attribute_methods/primary_key.rb:96:in `get_primary_key'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/attribute_methods/primary_key.rb:83:in `reset_primary_key'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/attribute_methods/primary_key.rb:71:in `primary_key'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.2/app/models/good_job/lockable.rb:224:in `_advisory_lockable_column'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation/delegation.rb:108:in `public_send'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation/delegation.rb:108:in `block in method_missing'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation.rb:895:in `_scoping'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation.rb:433:in `scoping'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation/delegation.rb:108:in `method_missing'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.2/app/models/good_job/lockable.rb:101:in `block (2 levels) in <module:Lockable>'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation.rb:440:in `instance_exec'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation.rb:440:in `block in _exec_scope'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation.rb:895:in `_scoping'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation.rb:440:in `_exec_scope'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/scoping/named.rb:175:in `block in scope'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation/delegation.rb:67:in `block in advisory_unlocked'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation.rb:895:in `_scoping'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation.rb:433:in `scoping'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation/delegation.rb:67:in `advisory_unlocked'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.2/app/models/good_job/process.rb:26:in `block in <class:Process>'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation.rb:440:in `instance_exec'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation.rb:440:in `block in _exec_scope'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation.rb:895:in `_scoping'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/relation.rb:440:in `_exec_scope'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activerecord/lib/active_record/scoping/named.rb:175:in `block in scope'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.2/app/models/good_job/process.rb:57:in `cleanup'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.2/lib/good_job/notifier/process_registration.rb:17:in `block in register_process'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.2/lib/good_job/assignable_connection.rb:32:in `with_connection'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.2/lib/good_job/notifier/process_registration.rb:16:in `register_process'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activesupport/lib/active_support/callbacks.rb:401:in `block in make_lambda'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activesupport/lib/active_support/callbacks.rb:272:in `block in simple'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activesupport/lib/active_support/callbacks.rb:600:in `block in invoke_after'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activesupport/lib/active_support/callbacks.rb:600:in `each'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activesupport/lib/active_support/callbacks.rb:600:in `invoke_after'",
"~/.rvm/gems/ruby-3.1.3@rails71/bundler/gems/rails-d247f491a4e4/activesupport/lib/active_support/callbacks.rb:109:in `run_callbacks'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.2/lib/good_job/notifier.rb:171:in `block (2 levels) in listen'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.2/lib/good_job/notifier.rb:215:in `with_connection'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/good_job-3.7.2/lib/good_job/notifier.rb:169:in `block in listen'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `block in synchronize'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `synchronize'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:47:in `synchronize'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22:in `execute'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/ivar.rb:169:in `safe_execute'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/scheduled_task.rb:298:in `process_task'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/timer_set.rb:98:in `block in ns_post_task'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:352:in `run_task'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:343:in `block (3 levels) in create_worker'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `loop'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:334:in `block (2 levels) in create_worker'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `catch'",
"~/.rvm/gems/ruby-3.1.3@rails71/gems/concurrent-ruby-1.1.10/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:333:in `block in create_worker'"]
12:07:21 goodjob.1 | [GoodJob] Notifier subscribed with LISTEN
About this issue
- Original URL
- State: closed
- Created a year ago
- Reactions: 1
- Comments: 20 (19 by maintainers)
@zarqman it looks like the upstream Rails fix has been merged 🎉
fyi, this is currently in the Rails 7.1 release milestone so I’m hopeful a fix is coming.
Oh no, rails are so slow on accepting fixes (attention to detail). 😃 @bensheldon has been known to fix my bug reports within minutes from reporting hehe
Shame it was a rails thing but cest la vie