bensheldon / good_job

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

`PG::AmbiguousColumn` after upgrade to 4.5.0 #1551

Closed luizkowalski closed 23 hours ago

luizkowalski commented 4 days ago

hey 👋🏻

After upgrading to 4.5.0, I'm seeing this error

[GoodJob] [50744] GoodJob 4.5.0 started scheduler with queues=* max_threads=5.
[GoodJob] Notifier subscribed with LISTEN
[GoodJob] GoodJob error: ActiveRecord::StatementInvalid: PG::AmbiguousColumn: ERROR:  column reference "id" is ambiguous
LINE 1: ... NULLS LAST, "good_jobs"."created_at" ASC) SELECT "rows"."id...

I can't tell exactly what's going on because the output is just messy

["/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb:160:in `exec'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/postgresql/database_statements.rb:160:in `perform_query'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:556:in `block (2 levels) in raw_execute'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:1011:in `block in with_raw_connection'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activesupport/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:983:in `with_raw_connection'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:555:in `block in raw_execute'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activesupport/lib/active_support/notifications/instrumenter.rb:58:in `instrument'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract_adapter.rb:1129:in `log'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:554:in `raw_execute'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:591:in `internal_execute'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:547:in `internal_exec_query'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:693:in `select'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract/database_statements.rb:73:in `select_all'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:248:in `block in select_all'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:286:in `block (2 levels) in cache_sql'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:80:in `compute_if_absent'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:284:in `block in cache_sql'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activesupport/lib/active_support/concurrency/null_lock.rb:9:in `synchronize'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:283:in `cache_sql'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract/query_cache.rb:248:in `select_all'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/querying.rb:68:in `_query_by_sql'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation.rb:1449:in `block (2 levels) in exec_main_query'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb:406:in `with_connection'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/connection_handling.rb:310:in `with_connection'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation.rb:1448:in `block in exec_main_query'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation.rb:1470:in `skip_query_cache_if_necessary'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation.rb:1432:in `exec_main_query'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation.rb:1410:in `block in exec_queries'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation.rb:1470:in `skip_query_cache_if_necessary'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation.rb:1404:in `exec_queries'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation.rb:1181:in `load'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation.rb:343:in `records'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation.rb:338:in `to_ary'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/good_job-4.5.0/app/models/concerns/good_job/advisory_lockable.rb:169:in `with_advisory_lock'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation/delegation.rb:81:in `block in with_advisory_lock'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation.rb:1373:in `_scoping'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation.rb:548:in `scoping'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation/delegation.rb:81:in `with_advisory_lock'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/good_job-4.5.0/app/models/good_job/job.rb:293:in `perform_with_advisory_lock'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation/delegation.rb:131:in `public_send'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation/delegation.rb:131:in `block in method_missing'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation.rb:1373:in `_scoping'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation.rb:548:in `scoping'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activerecord/lib/active_record/relation/delegation.rb:131:in `method_missing'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/good_job-4.5.0/lib/good_job/job_performer.rb:35:in `block in next'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/good_job-4.5.0/lib/good_job/capsule_tracker.rb:94:in `register'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/good_job-4.5.0/lib/good_job/job_performer.rb:34:in `next'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/good_job-4.5.0/lib/good_job/scheduler.rb:276:in `block (2 levels) in create_task'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activesupport/lib/active_support/reloader.rb:77:in `block in wrap'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activesupport/lib/active_support/execution_wrapper.rb:91:in `wrap'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/bundler/gems/rails-a23de8e5a415/activesupport/lib/active_support/reloader.rb:74:in `wrap'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/good_job-4.5.0/lib/good_job/scheduler.rb:275:in `block in create_task'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:24:in `block in execute'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `block in synchronize'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/synchronization/mutex_lockable_object.rb:48:in `synchronize'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/safe_task_executor.rb:22:in `execute'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/ivar.rb:170:in `safe_execute'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/scheduled_task.rb:298:in `process_task'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/timer_set.rb:98:in `block in ns_post_task'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:359:in `run_task'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:350:in `block (3 levels) in create_worker'", ":187:in `loop'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:341:in `block (2 levels) in create_worker'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `catch'", "/Users/luiz/.rbenv/versions/3.3.6/lib/ruby/gems/3.3.0/gems/concurrent-ruby-1.3.4/lib/concurrent-ruby/concurrent/executor/ruby_thread_pool_executor.rb:340:in `block in create_worker'"]

I vaguely remember dealing with something similar in the past, but I haven't found anything in issues or PRs. I will keep looking

I'm using PG 17.2 and Rails from main

bensheldon commented 4 days ago

Sorry about that! What version were previously upgrading from?

luizkowalski commented 4 days ago

4.4.2

luizkowalski commented 3 days ago

alright, good news, it is not good_job. I tried to downgrade GJ, PG, etc, nothing worked. then I realized it actually looks like Rails' fault and I tracked it down to this commit not sure if GJ needs to adjust something or this is actually a regression on Rails

bensheldon commented 3 days ago

Ooof! Thank you so much for tracking this down.

Sounds like the solution when upgrading to Rails 8 is to use the rails-v8.0 release branch?

bensheldon commented 3 days ago

Oh wait, are you saying that commit newly breaks it? Or that it fixes it?

luizkowalski commented 3 days ago

breaks, yeah

bensheldon commented 3 days ago

Ohhh! Can you share the whole SQL query? I was imagining that would help me leave a comment to the PR associated with the commit, but you could also do so. I think it would be good to report this as a regression in Rails

luizkowalski commented 3 days ago
SELECT "good_jobs"."id",
       "good_jobs"."queue_name",
       "good_jobs"."priority",
       "good_jobs"."serialized_params",
       "good_jobs"."scheduled_at",
       "good_jobs"."performed_at",
       "good_jobs"."finished_at",
       "good_jobs"."error",
       "good_jobs"."created_at",
       "good_jobs"."updated_at",
       "good_jobs"."active_job_id",
       "good_jobs"."concurrency_key",
       "good_jobs"."cron_key",
       "good_jobs"."cron_at",
       "good_jobs"."batch_id",
       "good_jobs"."batch_callback_id",
       "good_jobs"."executions_count",
       "good_jobs"."job_class",
       "good_jobs"."error_event",
       "good_jobs"."labels",
       "good_jobs"."locked_by_id",
       "good_jobs"."locked_at"
FROM "good_jobs"
WHERE "good_jobs"."id" IN
    (WITH "rows" AS MATERIALIZED
       (SELECT "good_jobs"."id", "good_jobs"."id"
        FROM "good_jobs"
        WHERE "good_jobs"."queue_name" = 'default'
          AND "good_jobs"."finished_at" IS NULL
          AND ("good_jobs"."scheduled_at" <= '2024-11-26 09:31:31.736649'
               OR "good_jobs"."scheduled_at" IS NULL)
        ORDER BY priority ASC NULLS LAST, "good_jobs"."created_at" ASC) SELECT "rows"."id"
     FROM "rows"
     WHERE pg_try_advisory_lock(('x' || substr(md5('good_jobs' || '-' || "rows"."id"::text), 1, 16))::bit(64)::bigint)
     LIMIT 1)
ORDER BY priority ASC NULLS LAST,
         "good_jobs"."created_at" ASC

I opened an issue on Rails too

Earlopain commented 3 days ago

Here maybe https://github.com/bensheldon/good_job/blob/5f8465991b03a284a35db8866c8b921585262474/app/models/concerns/good_job/advisory_lockable.rb#L45

That whole function is doing a bunch of arel stuff and may not end up in the right codepath now to dedupe these. Arel is supposed to be rails-internals only, though in practice it often isn't so.

luizkowalski commented 23 hours ago

tested main branch, can confirm it is working. thank you all <3