PG::AmbiguousColumn after upgrade to 4.5.0

[luizkowalski]

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'", "<internal:kernel>: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]

Sorry about that! What version were previously upgrading from?

[luizkowalski]

4.4.2

[luizkowalski]

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]

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]

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

[luizkowalski]

breaks, yeah

[bensheldon]

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]

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]

Here maybe

good_job/app/models/concerns/good_job/advisory_lockable.rb

Line 45 in 5f84659

cte_query = original_query.select(primary_key, column).except(:limit)

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]

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