search

bensheldon / good_job

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

Flaky test in Batches #1440

Open bensheldon opened 2 months ago

bensheldon commented 2 months ago

There is a test flake somewhere in here that maybe starts with calls success callbacks

Batches
  adding to an existing batch
    RUNNING: adds jobs to the existing batch
    adds jobs to the existing batch
  job that errors once then succeeds
    RUNNING: calls the success callbacks
    calls the success callbacks
  aggressive async batching
    RUNNING: can execute multiple jobs
    can execute multiple jobs
  complex batching
    RUNNING: can be used as instance object
    can be used as instance object
  all callbacks are called and retryable
    RUNNING: calls success callbacks
Connection returned to pool with 1 advisory locks
Connection returned to pool with 2 advisory locks
Connection returned to pool with 2 advisory locks
Connection returned to pool with 2 advisory locks
Connection returned to pool with 2 advisory locks
There are 2 advisory locks still open by the current database connection AFTER test run.

Advisory locked executions:
  - Execution ID: 0d10e67f-c5d9-4643-956a-84a7ea62e09e / Active Job ID: 0d10e67f-c5d9-4643-956a-84a7ea62e09e
  - Execution ID: 1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db / Active Job ID: 1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db

Advisory Locks:
  - 1057: RSpec: calls success callbacks
  - 1057: RSpec: calls success callbacks

Current connections:
  - 67: 
  - 68: 
  - 1057: RSpec: calls success callbacks
  - 64: 
  - 63: 
  - 66: 
Connection returned to pool with 2 advisory locks
    calls success callbacks (FAILED - 1)

  1) Batches all callbacks are called and retryable calls success callbacks
     Got 2 failures:

     1.1) Failure/Error: expect(PgLock.current_database.advisory_lock.owns.count).to eq(0), "Existing owned advisory locks AFTER test run"
            Existing owned advisory locks AFTER test run
          # ./spec/support/reset_good_job.rb:92:in `block (2 levels) in <main>'
          # ./spec/support/reset_rails_queue_adapter.rb:27:in `block (2 levels) in <main>'
          # ./spec/support/reset_good_job.rb:29:in `block (2 levels) in <main>'
          # ./spec/support/rails_executor.rb:19:in `block (3 levels) in <main>'
          # ./spec/support/rails_executor.rb:17:in `block (2 levels) in <main>'
          # ./spec/support/postgres_notices.rb:33:in `block (2 levels) in <main>'
          # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
          # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'

     1.2) Failure/Error: expect(POSTGRES_NOTICES).to be_empty
            expected `["Connection returned to pool with 1 advisory locks", "Connection returned to pool with 2 advisory locks", "Connection returned to pool with 2 advisory locks", "Connection returned to pool with 2 advisory locks", "Connection returned to pool with 2 advisory locks", "Connection returned to pool with 2 advisory locks"].empty?` to be truthy, got false
          # ./spec/support/postgres_notices.rb:34:in `block (2 levels) in <main>'
          # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
          # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'
    RUNNING: calls discard callbacks
Connection returned to pool with 2 advisory locks
    calls discard callbacks (FAILED - 2)

  2) Batches all callbacks are called and retryable calls discard callbacks
     Failure/Error: expect(PgLock.current_database.advisory_lock.count).to eq(0), "Existing advisory locks BEFORE test run"
       Existing advisory locks BEFORE test run
     # ./spec/support/reset_good_job.rb:21:in `block (2 levels) in <main>'
     # ./spec/support/rails_executor.rb:19:in `block (3 levels) in <main>'
     # ./spec/support/rails_executor.rb:17:in `block (2 levels) in <main>'
     # ./spec/support/postgres_notices.rb:33:in `block (2 levels) in <main>'
     # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
     # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'
  complex recursive batching
    RUNNING: can enqueue multiple jobs
Connection returned to pool with 2 advisory locks
    can enqueue multiple jobs (FAILED - 3)

  3) Batches complex recursive batching can enqueue multiple jobs
     Failure/Error: expect(PgLock.current_database.advisory_lock.count).to eq(0), "Existing advisory locks BEFORE test run"
       Existing advisory locks BEFORE test run
     # ./spec/support/reset_good_job.rb:21:in `block (2 levels) in <main>'
     # ./spec/support/rails_executor.rb:19:in `block (3 levels) in <main>'
     # ./spec/support/rails_executor.rb:17:in `block (2 levels) in <main>'
     # ./spec/support/postgres_notices.rb:33:in `block (2 levels) in <main>'
     # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
     # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'
  simple batching
    RUNNING: assigns a batch_id to all jobs in the batch
Connection returned to pool with 2 advisory locks
    assigns a batch_id to all jobs in the batch (FAILED - 4)

  4) Batches simple batching assigns a batch_id to all jobs in the batch
     Failure/Error: expect(PgLock.current_database.advisory_lock.count).to eq(0), "Existing advisory locks BEFORE test run"
       Existing advisory locks BEFORE test run
     # ./spec/support/reset_good_job.rb:21:in `block (2 levels) in <main>'
     # ./spec/support/rails_executor.rb:19:in `block (3 levels) in <main>'
     # ./spec/support/rails_executor.rb:17:in `block (2 levels) in <main>'
     # ./spec/support/postgres_notices.rb:33:in `block (2 levels) in <main>'
     # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
     # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'
    when a job is discarded
      RUNNING: has a failure status
Connection returned to pool with 1 advisory locks
Connection returned to pool with 1 advisory locks
Connection returned to pool with 1 advisory locks
There are 1 advisory locks still open by the current database connection AFTER test run.

Advisory locked executions:
  - Execution ID: 7fe84c60-3ae1-4200-b0e1-fe4d7009141f / Active Job ID: 7fe84c60-3ae1-4200-b0e1-fe4d7009141f

Advisory Locks:
  - 1057: RSpec: has a failure status

Current connections:
  - 67: 
  - 68: 
  - 1057: RSpec: has a failure status
  - 64: 
  - 63: 
  - 66: 
Connection returned to pool with 1 advisory locks
      has a failure status (FAILED - 5)

  5) Batches simple batching when a job is discarded has a failure status
     Got 2 failures:

     5.1) Failure/Error: expect(PgLock.current_database.advisory_lock.owns.count).to eq(0), "Existing owned advisory locks AFTER test run"
            Existing owned advisory locks AFTER test run
          # ./spec/support/reset_good_job.rb:92:in `block (2 levels) in <main>'
          # ./spec/support/reset_rails_queue_adapter.rb:27:in `block (2 levels) in <main>'
          # ./spec/support/reset_good_job.rb:29:in `block (2 levels) in <main>'
          # ./spec/support/rails_executor.rb:19:in `block (3 levels) in <main>'
          # ./spec/support/rails_executor.rb:17:in `block (2 levels) in <main>'
          # ./spec/support/postgres_notices.rb:33:in `block (2 levels) in <main>'
          # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
          # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'

     5.2) Failure/Error: expect(POSTGRES_NOTICES).to be_empty
            expected `["Connection returned to pool with 1 advisory locks", "Connection returned to pool with 1 advisory locks", "Connection returned to pool with 1 advisory locks", "Connection returned to pool with 1 advisory locks"].empty?` to be truthy, got false
          # ./spec/support/postgres_notices.rb:34:in `block (2 levels) in <main>'
          # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
          # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'
    when all jobs complete successfully
      RUNNING: has success status
Connection returned to pool with 1 advisory locks
      has success status (FAILED - 6)

  6) Batches simple batching when all jobs complete successfully has success status
     Failure/Error: expect(PgLock.current_database.advisory_lock.count).to eq(0), "Existing advisory locks BEFORE test run"
       Existing advisory locks BEFORE test run
     # ./spec/support/reset_good_job.rb:21:in `block (2 levels) in <main>'
     # ./spec/support/rails_executor.rb:19:in `block (3 levels) in <main>'
     # ./spec/support/rails_executor.rb:17:in `block (2 levels) in <main>'
     # ./spec/support/postgres_notices.rb:33:in `block (2 levels) in <main>'
     # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
     # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'
    when there is a callback
      RUNNING: calls the callback with a batch
Connection returned to pool with 1 advisory locks
      calls the callback with a batch (FAILED - 7)

  7) Batches simple batching when there is a callback calls the callback with a batch
     Failure/Error: expect(PgLock.current_database.advisory_lock.count).to eq(0), "Existing advisory locks BEFORE test run"
       Existing advisory locks BEFORE test run
     # ./spec/support/reset_good_job.rb:21:in `block (2 levels) in <main>'
     # ./spec/support/rails_executor.rb:19:in `block (3 levels) in <main>'
     # ./spec/support/rails_executor.rb:17:in `block (2 levels) in <main>'
     # ./spec/support/postgres_notices.rb:33:in `block (2 levels) in <main>'
     # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
     # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'
  when running inline
    RUNNING: does not unintentionally add sub-enqueued job to the batch
Connection returned to pool with 1 advisory locks
    does not unintentionally add sub-enqueued job to the batch (FAILED - 8)

  8) Batches when running inline does not unintentionally add sub-enqueued job to the batch
     Failure/Error: expect(PgLock.current_database.advisory_lock.count).to eq(0), "Existing advisory locks BEFORE test run"
       Existing advisory locks BEFORE test run
     # ./spec/support/reset_good_job.rb:21:in `block (2 levels) in <main>'
     # ./spec/support/rails_executor.rb:19:in `block (3 levels) in <main>'
     # ./spec/support/rails_executor.rb:17:in `block (2 levels) in <main>'
     # ./spec/support/postgres_notices.rb:33:in `block (2 levels) in <main>'
     # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
     # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'

GoodJob::ActiveJobExtensions::Batches
  enequeue
    when job does not have GoodJob Adapter
      RUNNING: warns when enqueued in a batch capture block
Connection returned to pool with 1 advisory locks
      warns when enqueued in a batch capture block (FAILED - 9)

  9) GoodJob::ActiveJobExtensions::Batches enequeue when job does not have GoodJob Adapter warns when enqueued in a batch capture block
     Failure/Error: expect(PgLock.current_database.advisory_lock.count).to eq(0), "Existing advisory locks BEFORE test run"
       Existing advisory locks BEFORE test run
     # ./spec/support/reset_good_job.rb:21:in `block (2 levels) in <main>'
     # ./spec/support/rails_executor.rb:19:in `block (3 levels) in <main>'
     # ./spec/support/rails_executor.rb:17:in `block (2 levels) in <main>'
     # ./spec/support/postgres_notices.rb:33:in `block (2 levels) in <main>'
     # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
     # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'
      RUNNING: warns when directly added to a batch
Connection returned to pool with 1 advisory locks
      warns when directly added to a batch (FAILED - 10)

  10) GoodJob::ActiveJobExtensions::Batches enequeue when job does not have GoodJob Adapter warns when directly added to a batch
      Failure/Error: expect(PgLock.current_database.advisory_lock.count).to eq(0), "Existing advisory locks BEFORE test run"
        Existing advisory locks BEFORE test run
      # ./spec/support/reset_good_job.rb:21:in `block (2 levels) in <main>'
      # ./spec/support/rails_executor.rb:19:in `block (3 levels) in <main>'
      # ./spec/support/rails_executor.rb:17:in `block (2 levels) in <main>'
      # ./spec/support/postgres_notices.rb:33:in `block (2 levels) in <main>'
      # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
      # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'
      RUNNING: warns when enqueued in a bulk capture block
      warns when enqueued in a bulk capture block
  batch accessors
    RUNNING: does not leak batch into perform_now
    does not leak batch into perform_now
    RUNNING: access batch
    access batch

GoodJob::CronManager
  schedules
    RUNNING: respects the disabled setting
    respects the disabled setting
    RUNNING: only inserts unique jobs when multiple CronManagers are running
    only inserts unique jobs when multiple CronManagers are running
    RUNNING: executes the defined tasks
    executes the defined tasks
    when schedule is a proc
      RUNNING: executes the defined tasks
      executes the defined tasks
bensheldon commented 2 months ago
Log entries ``` ---- START EXAMPLE: Batches all callbacks are called and retryable calls success callbacks (./spec/integration/batch_spec.rb:227) [🐄 RSpec: calls success callbacks 🐄] Set application name (0.2ms) SET application_name = 'RSpec: calls success callbacks' [🐄 RSpec: calls success callbacks 🐄] PgLock Count (0.3ms) SELECT COUNT(*) FROM "pg_locks" WHERE "pg_locks"."locktype" = $1 AND (pid = pg_backend_pid()) [["locktype", "advisory"]] [🐄 RSpec: calls success callbacks 🐄] PgLock Count (0.3ms) SELECT COUNT(*) FROM "pg_locks" WHERE "pg_locks"."locktype" = $1 AND (pid != pg_backend_pid()) [["locktype", "advisory"]] [🐄 RSpec: calls success callbacks 🐄] PgLock Count (0.4ms) SELECT COUNT(*) FROM "pg_locks" JOIN pg_database ON pg_database.oid = pg_locks.database WHERE (pg_database.datname = current_database()) AND "pg_locks"."locktype" = $1 [["locktype", "advisory"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.2ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::BatchRecord Create (0.4ms) INSERT INTO "good_job_batches" ("created_at", "updated_at", "description", "serialized_properties", "on_finish", "on_success", "on_discard", "callback_queue_name", "callback_priority", "enqueued_at", "discarded_at", "finished_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12) RETURNING "id" [["created_at", "2024-07-18 14:21:20.092068"], ["updated_at", "2024-07-18 14:21:20.092068"], ["description", nil], ["serialized_properties", "{\"user\":\"Alice\",\"_aj_symbol_keys\":[\"user\"]}"], ["on_finish", "RetriedJob"], ["on_success", "RetriedJob"], ["on_discard", "RetriedJob"], ["callback_queue_name", nil], ["callback_priority", nil], ["enqueued_at", nil], ["discarded_at", nil], ["finished_at", nil]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] Enqueued TestJob (Job ID: 123be496-7ea4-4f01-a49b-e137f0fc528e) to (default) [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Insert (0.8ms) INSERT INTO "good_jobs" ("id","queue_name","priority","serialized_params","scheduled_at","performed_at","finished_at","error","created_at","updated_at","active_job_id","concurrency_key","cron_key","cron_at","batch_id","batch_callback_id","executions_count","job_class","error_event","labels","locked_by_id","locked_at") VALUES ('123be496-7ea4-4f01-a49b-e137f0fc528e', 'default', 0, '{"job_class":"TestJob","job_id":"123be496-7ea4-4f01-a49b-e137f0fc528e","provider_job_id":null,"queue_name":"default","priority":null,"arguments":[],"executions":0,"exception_executions":{},"locale":"en","timezone":"UTC","enqueued_at":"2024-07-18T14:21:20Z"}', '2024-07-18 14:21:20.093863', NULL, NULL, NULL, '2024-07-18 14:21:20.093863', '2024-07-18 14:21:20.093863', '123be496-7ea4-4f01-a49b-e137f0fc528e', NULL, NULL, NULL, '948cd0fe-466c-46fb-87fa-781dbc82d451', NULL, NULL, 'TestJob', NULL, NULL, NULL, NULL) ON CONFLICT DO NOTHING RETURNING "id","active_job_id" [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] SQL (0.2ms) NOTIFY good_job, '{"queue_name":"default","count":1,"scheduled_at":"2024-07-18T14:21:20.093Z"}' [🐄 RSpec: calls success callbacks 🐄] (0.3ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐄 RSpec: calls success callbacks 🐄] Set application name (0.2ms) SET application_name = 'RSpec: calls success callbacks' [🐄 RSpec: calls success callbacks 🐄] GoodJob::Lockable Advisory Lock (0.5ms) SELECT pg_advisory_lock(('x'||substr(md5($1::text), 1, 16))::bit(64)::bigint)::text AS locked [["key", "good_job_batches-948cd0fe-466c-46fb-87fa-781dbc82d451"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::BatchRecord Update (0.3ms) UPDATE "good_job_batches" SET "updated_at" = $1, "enqueued_at" = $2 WHERE "good_job_batches"."id" = $3 [["updated_at", "2024-07-18 14:21:20.098592"], ["enqueued_at", "2024-07-18 14:21:20.098169"], ["id", "948cd0fe-466c-46fb-87fa-781dbc82d451"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] GoodJob::BatchRecord Load (0.2ms) SELECT "good_job_batches".* FROM "good_job_batches" WHERE "good_job_batches"."id" = $1 LIMIT $2 [["id", "948cd0fe-466c-46fb-87fa-781dbc82d451"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Count (0.5ms) SELECT COUNT(*) FROM "good_jobs" WHERE "good_jobs"."batch_id" = $1 AND "good_jobs"."finished_at" IS NULL [["batch_id", "948cd0fe-466c-46fb-87fa-781dbc82d451"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Lockable Advisory Unlock (0.3ms) SELECT pg_advisory_unlock(('x'||substr(md5($1::text), 1, 16))::bit(64)::bigint) AS unlocked [["key", "good_job_batches-948cd0fe-466c-46fb-87fa-781dbc82d451"]] [🐄 RSpec: calls success callbacks 🐄] (0.3ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐄 RSpec: calls success callbacks 🐄] Set application name (0.2ms) SET application_name = 'RSpec: calls success callbacks' [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Process Create (0.4ms) INSERT INTO "good_job_processes" ("id", "created_at", "updated_at", "state", "lock_type") VALUES ($1, $2, $3, $4, $5) RETURNING "id" [["id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["created_at", "2024-07-18 14:21:20.103699"], ["updated_at", "2024-07-18 14:21:20.103699"], ["state", "{\"hostname\":\"fv-az1149-759\",\"pid\":3685,\"proctitle\":\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/bin/rspec\",\"preserve_job_records\":true,\"retry_on_unhandled_error\":false,\"schedulers\":[],\"cron_enabled\":false,\"total_succeeded_executions_count\":0,\"total_errored_executions_count\":0,\"database_connection_pool\":{\"size\":20,\"active\":0}}"], ["lock_type", nil]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Load (1.0ms) 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" FROM "good_jobs" WHERE "good_jobs"."finished_at" IS NULL AND ("good_jobs"."scheduled_at" <= $1 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 $2) ORDER BY priority ASC NULLS LAST, "good_jobs"."created_at" ASC [["scheduled_at", "2024-07-18 14:21:20.105450"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Load (0.3ms) 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" = $1 LIMIT $2 [["id", "123be496-7ea4-4f01-a49b-e137f0fc528e"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.2ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Execution Create (0.5ms) INSERT INTO "good_job_executions" ("created_at", "updated_at", "active_job_id", "job_class", "queue_name", "serialized_params", "scheduled_at", "finished_at", "error", "error_event", "error_backtrace", "process_id", "duration") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13) RETURNING "id" [["created_at", "2024-07-18 14:21:20.108479"], ["updated_at", "2024-07-18 14:21:20.109411"], ["active_job_id", "123be496-7ea4-4f01-a49b-e137f0fc528e"], ["job_class", "TestJob"], ["queue_name", "default"], ["serialized_params", "{\"job_id\":\"123be496-7ea4-4f01-a49b-e137f0fc528e\",\"locale\":\"en\",\"priority\":null,\"timezone\":\"UTC\",\"arguments\":[],\"job_class\":\"TestJob\",\"executions\":0,\"queue_name\":\"default\",\"enqueued_at\":\"2024-07-18T14:21:20Z\",\"provider_job_id\":null,\"exception_executions\":{}}"], ["scheduled_at", "2024-07-18 14:21:20.093863"], ["finished_at", nil], ["error", nil], ["error_event", nil], ["error_backtrace", nil], ["process_id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["duration", nil]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update (0.4ms) UPDATE "good_jobs" SET "performed_at" = $1, "updated_at" = $2, "executions_count" = $3, "locked_by_id" = $4, "locked_at" = $5 WHERE "good_jobs"."id" = $6 [["performed_at", "2024-07-18 14:21:20.108479"], ["updated_at", "2024-07-18 14:21:20.110821"], ["executions_count", 1], ["locked_by_id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["locked_at", "2024-07-18 14:21:20.108824"], ["id", "123be496-7ea4-4f01-a49b-e137f0fc528e"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [TestJob] [123be496-7ea4-4f01-a49b-e137f0fc528e] Performing TestJob (Job ID: 123be496-7ea4-4f01-a49b-e137f0fc528e) from (default) enqueued at 2024-07-18T14:21:20Z [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [TestJob] [123be496-7ea4-4f01-a49b-e137f0fc528e] Performed TestJob (Job ID: 123be496-7ea4-4f01-a49b-e137f0fc528e) from (default) in 0.14ms [🐄 RSpec: calls success callbacks 🐄] [GoodJob] [3685] [RSpec: calls success callbacks] Executed GoodJob 123be496-7ea4-4f01-a49b-e137f0fc528e [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.2ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Execution Update (0.3ms) UPDATE "good_job_executions" SET "updated_at" = $1, "finished_at" = $2, "duration" = $3 WHERE "good_job_executions"."id" = $4 [["updated_at", "2024-07-18 14:21:20.113405"], ["finished_at", "2024-07-18 14:21:20.112930"], ["duration", "PT0.0044511880000186466S"], ["id", "024f7cfb-6d4c-48ad-8d68-6136313a1ccc"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update (0.6ms) UPDATE "good_jobs" SET "locked_by_id" = $1, "locked_at" = $2, "finished_at" = $3, "updated_at" = $4 WHERE "good_jobs"."id" = $5 [["locked_by_id", nil], ["locked_at", nil], ["finished_at", "2024-07-18 14:21:20.112930"], ["updated_at", "2024-07-18 14:21:20.114405"], ["id", "123be496-7ea4-4f01-a49b-e137f0fc528e"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] GoodJob::Lockable Advisory Unlock (0.2ms) SELECT pg_advisory_unlock(('x'||substr(md5($1::text), 1, 16))::bit(64)::bigint) AS unlocked [["key", "good_jobs-123be496-7ea4-4f01-a49b-e137f0fc528e"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::BatchRecord Load (0.3ms) SELECT "good_job_batches".* FROM "good_job_batches" WHERE "good_job_batches"."id" = $1 LIMIT $2 [["id", "948cd0fe-466c-46fb-87fa-781dbc82d451"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Lockable Advisory Lock (0.2ms) SELECT pg_advisory_lock(('x'||substr(md5($1::text), 1, 16))::bit(64)::bigint)::text AS locked [["key", "good_job_batches-948cd0fe-466c-46fb-87fa-781dbc82d451"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::BatchRecord Load (0.2ms) SELECT "good_job_batches".* FROM "good_job_batches" WHERE "good_job_batches"."id" = $1 LIMIT $2 [["id", "948cd0fe-466c-46fb-87fa-781dbc82d451"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Count (0.3ms) SELECT COUNT(*) FROM "good_jobs" WHERE "good_jobs"."batch_id" = $1 AND "good_jobs"."finished_at" IS NULL [["batch_id", "948cd0fe-466c-46fb-87fa-781dbc82d451"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::BatchRecord Update (0.2ms) UPDATE "good_job_batches" SET "updated_at" = $1, "finished_at" = $2 WHERE "good_job_batches"."id" = $3 [["updated_at", "2024-07-18 14:21:20.119493"], ["finished_at", "2024-07-18 14:21:20.119051"], ["id", "948cd0fe-466c-46fb-87fa-781dbc82d451"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] GoodJob::Job Create (0.4ms) INSERT INTO "good_jobs" ("id", "queue_name", "priority", "serialized_params", "scheduled_at", "performed_at", "finished_at", "error", "created_at", "updated_at", "active_job_id", "concurrency_key", "cron_key", "cron_at", "batch_id", "batch_callback_id", "executions_count", "job_class", "error_event", "labels", "locked_by_id", "locked_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16, $17, $18, $19, $20, $21, $22) RETURNING "id" [["id", "0d10e67f-c5d9-4643-956a-84a7ea62e09e"], ["queue_name", "default"], ["priority", 0], ["serialized_params", "{\"job_class\":\"RetriedJob\",\"job_id\":\"0d10e67f-c5d9-4643-956a-84a7ea62e09e\",\"provider_job_id\":null,\"queue_name\":\"default\",\"priority\":null,\"arguments\":[{\"_aj_globalid\":\"gid://test-app/GoodJob::Batch/948cd0fe-466c-46fb-87fa-781dbc82d451\"},{\"event\":{\"_aj_serialized\":\"ActiveJob::Serializers::SymbolSerializer\",\"value\":\"success\"},\"_aj_symbol_keys\":[\"event\"]}],\"executions\":0,\"exception_executions\":{},\"locale\":\"en\",\"timezone\":\"UTC\",\"enqueued_at\":\"2024-07-18T14:21:20Z\"}"], ["scheduled_at", "2024-07-18 14:21:20.120873"], ["performed_at", nil], ["finished_at", nil], ["error", nil], ["created_at", "2024-07-18 14:21:20.120873"], ["updated_at", "2024-07-18 14:21:20.121315"], ["active_job_id", "0d10e67f-c5d9-4643-956a-84a7ea62e09e"], ["concurrency_key", nil], ["cron_key", nil], ["cron_at", nil], ["batch_id", nil], ["batch_callback_id", "948cd0fe-466c-46fb-87fa-781dbc82d451"], ["executions_count", nil], ["job_class", "RetriedJob"], ["error_event", nil], ["labels", nil], ["locked_by_id", nil], ["locked_at", nil]] [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] SQL (0.2ms) NOTIFY good_job, '{"queue_name":"default","scheduled_at":"2024-07-18T14:21:20.120Z"}' [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] Enqueued RetriedJob (Job ID: 0d10e67f-c5d9-4643-956a-84a7ea62e09e) to (default) with arguments: #>, {:event=>:success} [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] GoodJob::Job Create (0.3ms) INSERT INTO "good_jobs" ("id", "queue_name", "priority", "serialized_params", "scheduled_at", "performed_at", "finished_at", "error", "created_at", "updated_at", "active_job_id", "concurrency_key", "cron_key", "cron_at", "batch_id", "batch_callback_id", "executions_count", "job_class", "error_event", "labels", "locked_by_id", "locked_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16, $17, $18, $19, $20, $21, $22) RETURNING "id" [["id", "1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db"], ["queue_name", "default"], ["priority", 0], ["serialized_params", "{\"job_class\":\"RetriedJob\",\"job_id\":\"1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db\",\"provider_job_id\":null,\"queue_name\":\"default\",\"priority\":null,\"arguments\":[{\"_aj_globalid\":\"gid://test-app/GoodJob::Batch/948cd0fe-466c-46fb-87fa-781dbc82d451\"},{\"event\":{\"_aj_serialized\":\"ActiveJob::Serializers::SymbolSerializer\",\"value\":\"finish\"},\"_aj_symbol_keys\":[\"event\"]}],\"executions\":0,\"exception_executions\":{},\"locale\":\"en\",\"timezone\":\"UTC\",\"enqueued_at\":\"2024-07-18T14:21:20Z\"}"], ["scheduled_at", "2024-07-18 14:21:20.123690"], ["performed_at", nil], ["finished_at", nil], ["error", nil], ["created_at", "2024-07-18 14:21:20.123690"], ["updated_at", "2024-07-18 14:21:20.124091"], ["active_job_id", "1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db"], ["concurrency_key", nil], ["cron_key", nil], ["cron_at", nil], ["batch_id", nil], ["batch_callback_id", "948cd0fe-466c-46fb-87fa-781dbc82d451"], ["executions_count", nil], ["job_class", "RetriedJob"], ["error_event", nil], ["labels", nil], ["locked_by_id", nil], ["locked_at", nil]] [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] SQL (0.1ms) NOTIFY good_job, '{"queue_name":"default","scheduled_at":"2024-07-18T14:21:20.123Z"}' [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] Enqueued RetriedJob (Job ID: 1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db) to (default) with arguments: #>, {:event=>:finish} [🐄 RSpec: calls success callbacks 🐄] GoodJob::Lockable Advisory Unlock (0.2ms) SELECT pg_advisory_unlock(('x'||substr(md5($1::text), 1, 16))::bit(64)::bigint) AS unlocked [["key", "good_job_batches-948cd0fe-466c-46fb-87fa-781dbc82d451"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Process Destroy (0.3ms) DELETE FROM "good_job_processes" WHERE "good_job_processes"."id" = $1 [["id", "664c4bd6-5530-4316-954a-f4604477fc1c"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update All (0.2ms) UPDATE "good_jobs" SET "locked_by_id" = $1 WHERE "good_jobs"."locked_by_id" = $2 [["locked_by_id", nil], ["locked_by_id", "664c4bd6-5530-4316-954a-f4604477fc1c"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.2ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] (0.3ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐄 RSpec: calls success callbacks 🐄] Set application name (0.1ms) SET application_name = 'RSpec: calls success callbacks' [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Process Create (0.2ms) INSERT INTO "good_job_processes" ("id", "created_at", "updated_at", "state", "lock_type") VALUES ($1, $2, $3, $4, $5) RETURNING "id" [["id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["created_at", "2024-07-18 14:21:20.129638"], ["updated_at", "2024-07-18 14:21:20.129638"], ["state", "{\"hostname\":\"fv-az1149-759\",\"pid\":3685,\"proctitle\":\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/bin/rspec\",\"preserve_job_records\":true,\"retry_on_unhandled_error\":false,\"schedulers\":[],\"cron_enabled\":false,\"total_succeeded_executions_count\":0,\"total_errored_executions_count\":0,\"database_connection_pool\":{\"size\":20,\"active\":0}}"], ["lock_type", nil]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.2ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Load (0.6ms) 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" FROM "good_jobs" WHERE "good_jobs"."finished_at" IS NULL AND ("good_jobs"."scheduled_at" <= $1 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 $2) ORDER BY priority ASC NULLS LAST, "good_jobs"."created_at" ASC [["scheduled_at", "2024-07-18 14:21:20.131284"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Load (0.3ms) 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" = $1 LIMIT $2 [["id", "0d10e67f-c5d9-4643-956a-84a7ea62e09e"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Execution Create (0.3ms) INSERT INTO "good_job_executions" ("created_at", "updated_at", "active_job_id", "job_class", "queue_name", "serialized_params", "scheduled_at", "finished_at", "error", "error_event", "error_backtrace", "process_id", "duration") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13) RETURNING "id" [["created_at", "2024-07-18 14:21:20.133474"], ["updated_at", "2024-07-18 14:21:20.134346"], ["active_job_id", "0d10e67f-c5d9-4643-956a-84a7ea62e09e"], ["job_class", "RetriedJob"], ["queue_name", "default"], ["serialized_params", "{\"job_id\":\"0d10e67f-c5d9-4643-956a-84a7ea62e09e\",\"locale\":\"en\",\"priority\":null,\"timezone\":\"UTC\",\"arguments\":[{\"_aj_globalid\":\"gid://test-app/GoodJob::Batch/948cd0fe-466c-46fb-87fa-781dbc82d451\"},{\"event\":{\"value\":\"success\",\"_aj_serialized\":\"ActiveJob::Serializers::SymbolSerializer\"},\"_aj_symbol_keys\":[\"event\"]}],\"job_class\":\"RetriedJob\",\"executions\":0,\"queue_name\":\"default\",\"enqueued_at\":\"2024-07-18T14:21:20Z\",\"provider_job_id\":null,\"exception_executions\":{}}"], ["scheduled_at", "2024-07-18 14:21:20.120873"], ["finished_at", nil], ["error", nil], ["error_event", nil], ["error_backtrace", nil], ["process_id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["duration", nil]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update (0.3ms) UPDATE "good_jobs" SET "performed_at" = $1, "updated_at" = $2, "executions_count" = $3, "locked_by_id" = $4, "locked_at" = $5 WHERE "good_jobs"."id" = $6 [["performed_at", "2024-07-18 14:21:20.133474"], ["updated_at", "2024-07-18 14:21:20.135689"], ["executions_count", 1], ["locked_by_id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["locked_at", "2024-07-18 14:21:20.133804"], ["id", "0d10e67f-c5d9-4643-956a-84a7ea62e09e"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [0d10e67f-c5d9-4643-956a-84a7ea62e09e] GoodJob::BatchRecord Load (0.2ms) SELECT "good_job_batches".* FROM "good_job_batches" WHERE "good_job_batches"."id" = $1 LIMIT $2 [["id", "948cd0fe-466c-46fb-87fa-781dbc82d451"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [0d10e67f-c5d9-4643-956a-84a7ea62e09e] Performing RetriedJob (Job ID: 0d10e67f-c5d9-4643-956a-84a7ea62e09e) from (default) enqueued at 2024-07-18T14:21:20Z with arguments: #>, {:event=>:success} [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [0d10e67f-c5d9-4643-956a-84a7ea62e09e] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [0d10e67f-c5d9-4643-956a-84a7ea62e09e] GoodJob::Job Update (0.3ms) UPDATE "good_jobs" SET "performed_at" = $1, "serialized_params" = $2, "scheduled_at" = $3, "created_at" = $4, "updated_at" = $5 WHERE "good_jobs"."id" = $6 [["performed_at", nil], ["serialized_params", "{\"job_class\":\"RetriedJob\",\"job_id\":\"0d10e67f-c5d9-4643-956a-84a7ea62e09e\",\"provider_job_id\":\"0d10e67f-c5d9-4643-956a-84a7ea62e09e\",\"queue_name\":\"default\",\"priority\":null,\"arguments\":[{\"_aj_globalid\":\"gid://test-app/GoodJob::Batch/948cd0fe-466c-46fb-87fa-781dbc82d451\"},{\"event\":{\"_aj_serialized\":\"ActiveJob::Serializers::SymbolSerializer\",\"value\":\"success\"},\"_aj_symbol_keys\":[\"event\"]}],\"executions\":1,\"exception_executions\":{\"[\\\"RetryableError\\\"]\":1},\"locale\":\"en\",\"timezone\":\"UTC\",\"enqueued_at\":\"2024-07-18T14:21:20Z\"}"], ["scheduled_at", "2024-07-18 14:21:20.137917"], ["created_at", "2024-07-18 14:21:20.138066"], ["updated_at", "2024-07-18 14:21:20.138511"], ["id", "0d10e67f-c5d9-4643-956a-84a7ea62e09e"]] [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [0d10e67f-c5d9-4643-956a-84a7ea62e09e] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [0d10e67f-c5d9-4643-956a-84a7ea62e09e] SQL (0.2ms) NOTIFY good_job, '{"queue_name":"default","scheduled_at":"2024-07-18T14:21:20.137Z"}' [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [0d10e67f-c5d9-4643-956a-84a7ea62e09e] Enqueued RetriedJob (Job ID: 0d10e67f-c5d9-4643-956a-84a7ea62e09e) to (default) at 2024-07-18 14:21:20 UTC with arguments: #>, {:event=>:success} [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [0d10e67f-c5d9-4643-956a-84a7ea62e09e] Retrying RetriedJob in 0 seconds, due to a RetryableError. [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [0d10e67f-c5d9-4643-956a-84a7ea62e09e] Performed RetriedJob (Job ID: 0d10e67f-c5d9-4643-956a-84a7ea62e09e) from (default) in 8.77ms [🐄 RSpec: calls success callbacks 🐄] [GoodJob] [3685] [RSpec: calls success callbacks] Executed GoodJob 0d10e67f-c5d9-4643-956a-84a7ea62e09e [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Execution Update (0.9ms) UPDATE "good_job_executions" SET "updated_at" = $1, "finished_at" = $2, "error" = $3, "error_event" = $4, "error_backtrace" = $5, "duration" = $6 WHERE "good_job_executions"."id" = $7 [["updated_at", "2024-07-18 14:21:20.146608"], ["finished_at", "2024-07-18 14:21:20.146160"], ["error", "RetryableError: RetryableError"], ["error_event", 3], ["error_backtrace", "{\"/home/runner/work/good_job/good_job/spec/integration/batch_spec.rb:207:in `perform'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/execution.rb:65:in `block in _perform_job'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:118:in `block in run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/i18n-1.14.5/lib/i18n.rb:351:in `with_locale'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/translation.rb:9:in `block (2 levels) in '\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:127:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:127:in `block in run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/core_ext/time/zones.rb:65:in `use_zone'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/timezones.rb:9:in `block (2 levels) in '\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:127:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:127:in `block in run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:138:in `run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/execution.rb:64:in `_perform_job'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/instrumentation.rb:20:in `_perform_job'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/execution.rb:52:in `perform_now'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/instrumentation.rb:14:in `block in perform_now'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/instrumentation.rb:25:in `block in instrument'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/notifications.rb:206:in `block in instrument'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/notifications/instrumenter.rb:24:in `instrument'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/notifications.rb:206:in `instrument'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/instrumentation.rb:35:in `instrument'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/instrumentation.rb:14:in `perform_now'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/logging.rb:18:in `block in perform_now'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/tagged_logging.rb:99:in `block in tagged'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/tagged_logging.rb:37:in `tagged'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/tagged_logging.rb:99:in `tagged'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/logging.rb:25:in `tag_logger'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/logging.rb:18:in `perform_now'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/execution.rb:30:in `block in execute'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:118:in `block in run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/railtie.rb:54:in `block (4 levels) in '\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/execution_wrapper.rb:92:in `wrap'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/reloader.rb:72:in `block in wrap'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/execution_wrapper.rb:88:in `wrap'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/reloader.rb:71:in `wrap'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/railtie.rb:53:in `block (3 levels) in '\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:127:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:127:in `block in run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:138:in `run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/execution.rb:28:in `execute'\",\"/home/runner/work/good_job/good_job/app/models/good_job/job.rb:623:in `block (3 levels) in perform'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/notifications.rb:206:in `block in instrument'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/notifications/instrumenter.rb:24:in `instrument'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/notifications.rb:206:in `instrument'\",\"/home/runner/work/good_job/good_job/app/models/good_job/job.rb:622:in `block (2 levels) in perform'\",\"/home/runner/work/good_job/good_job/lib/good_job/current_thread.rb:113:in `within'\",\"/home/runner/work/good_job/good_job/app/models/good_job/job.rb:580:in `block in perform'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:118:in `block in run_callbacks'\",\"/home/runner/work/good_job/good_job/app/models/good_job/batch.rb:78:in `within_thread'\",\"/home/runner/work/good_job/good_job/app/models/good_job/job.rb:765:in `reset_batch_values'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:127:in `block in run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:138:in `run_callbacks'\",\"/home/runner/work/good_job/good_job/app/models/good_job/job.rb:574:in `perform'\",\"/home/runner/work/good_job/good_job/app/models/good_job/job.rb:322:in `block in perform_with_advisory_lock'\",\"/home/runner/work/good_job/good_job/app/models/concerns/good_job/advisory_lockable.rb:172:in `block in with_advisory_lock'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation.rb:881:in `_scoping'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation.rb:428:in `scoping'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/scoping/default.rb:43:in `unscoped'\",\"/home/runner/work/good_job/good_job/app/models/concerns/good_job/advisory_lockable.rb:172:in `with_advisory_lock'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation/delegation.rb:67:in `block in with_advisory_lock'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation.rb:881:in `_scoping'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation.rb:428:in `scoping'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation/delegation.rb:67:in `with_advisory_lock'\",\"/home/runner/work/good_job/good_job/app/models/good_job/job.rb:316:in `perform_with_advisory_lock'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation/delegation.rb:67:in `block in perform_with_advisory_lock'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation.rb:881:in `_scoping'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation.rb:428:in `scoping'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation/delegation.rb:67:in `perform_with_advisory_lock'\",\"/home/runner/work/good_job/good_job/lib/good_job/job_performer.rb:35:in `block in next'\",\"/home/runner/work/good_job/good_job/lib/good_job/capsule_tracker.rb:103:in `register'\",\"/home/runner/work/good_job/good_job/lib/good_job/job_performer.rb:34:in `next'\",\"/home/runner/work/good_job/good_job/lib/good_job.rb:261:in `block (2 levels) in perform_inline'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/execution_wrapper.rb:92:in `wrap'\",\"/home/runner/work/good_job/good_job/lib/good_job.rb:261:in `block in perform_inline'\",\"/home/runner/work/good_job/good_job/lib/good_job.rb:258:in `loop'\",\"/home/runner/work/good_job/good_job/lib/good_job.rb:258:in `perform_inline'\",\"/home/runner/work/good_job/good_job/spec/integration/batch_spec.rb:231:in `block (3 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:263:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:263:in `block in run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:511:in `block in with_around_and_singleton_context_hooks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:468:in `block in with_around_example_hooks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:486:in `block in run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:626:in `block in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-rails-6.1.3/lib/rspec/rails/adapters.rb:75:in `block (2 levels) in '\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:390:in `execute_with'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/spec/support/reset_rails_queue_adapter.rb:27:in `block (2 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:390:in `execute_with'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/spec/support/reset_good_job.rb:29:in `block (2 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:390:in `execute_with'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/spec/support/rails_executor.rb:19:in `block (3 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/execution_wrapper.rb:105:in `perform'\",\"/home/runner/work/good_job/good_job/spec/support/rails_executor.rb:17:in `block (2 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:390:in `execute_with'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/spec/support/postgres_notices.rb:33:in `block (2 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:390:in `execute_with'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/spec/support/logger.rb:7:in `block (2 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:390:in `execute_with'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/spec/support/database_cleaner.rb:17:in `block (2 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:390:in `execute_with'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:629:in `run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:486:in `run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:468:in `with_around_example_hooks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:511:in `with_around_and_singleton_context_hooks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:259:in `run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example_group.rb:646:in `block in run_examples'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example_group.rb:642:in `map'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example_group.rb:642:in `run_examples'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example_group.rb:607:in `run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example_group.rb:608:in `block in run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example_group.rb:608:in `map'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example_group.rb:608:in `run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:121:in `block (3 levels) in run_specs'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:121:in `map'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:121:in `block (2 levels) in run_specs'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/configuration.rb:2091:in `with_suite_hooks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:116:in `block in run_specs'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/reporter.rb:74:in `report'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:115:in `run_specs'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:89:in `run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:71:in `run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:45:in `invoke'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/exe/rspec:4:in `'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/bin/rspec:25:in `load'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/bin/rspec:25:in `'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli/exec.rb:58:in `load'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli/exec.rb:58:in `kernel_load'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli/exec.rb:23:in `run'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli.rb:479:in `exec'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli.rb:31:in `dispatch'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor/base.rb:485:in `start'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli.rb:25:in `start'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/exe/bundle:49:in `block in '\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/friendly_errors.rb:103:in `with_friendly_errors'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/exe/bundle:37:in `'\",\"/opt/hostedtoolcache/Ruby/3.0.7/x64/bin/bundle:25:in `load'\",\"/opt/hostedtoolcache/Ruby/3.0.7/x64/bin/bundle:25:in `
'\"}"], ["duration", "PT0.012659143999997013S"], ["id", "7fbb81d6-05ff-4b3a-bc6d-23058263c218"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update (0.3ms) UPDATE "good_jobs" SET "locked_by_id" = $1, "locked_at" = $2, "error" = $3, "updated_at" = $4, "error_event" = $5 WHERE "good_jobs"."id" = $6 [["locked_by_id", nil], ["locked_at", nil], ["error", "RetryableError: RetryableError"], ["updated_at", "2024-07-18 14:21:20.149264"], ["error_event", 3], ["id", "0d10e67f-c5d9-4643-956a-84a7ea62e09e"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] GoodJob::Lockable Advisory Unlock (0.2ms) SELECT pg_advisory_unlock(('x'||substr(md5($1::text), 1, 16))::bit(64)::bigint) AS unlocked [["key", "good_jobs-0d10e67f-c5d9-4643-956a-84a7ea62e09e"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Process Destroy (0.2ms) DELETE FROM "good_job_processes" WHERE "good_job_processes"."id" = $1 [["id", "664c4bd6-5530-4316-954a-f4604477fc1c"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update All (0.2ms) UPDATE "good_jobs" SET "locked_by_id" = $1 WHERE "good_jobs"."locked_by_id" = $2 [["locked_by_id", nil], ["locked_by_id", "664c4bd6-5530-4316-954a-f4604477fc1c"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] (0.3ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐄 RSpec: calls success callbacks 🐄] Connection returned to pool with 1 advisory locks [🐄 RSpec: calls success callbacks 🐄] Set application name (0.1ms) SET application_name = 'RSpec: calls success callbacks' [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Process Create (0.2ms) INSERT INTO "good_job_processes" ("id", "created_at", "updated_at", "state", "lock_type") VALUES ($1, $2, $3, $4, $5) RETURNING "id" [["id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["created_at", "2024-07-18 14:21:20.154238"], ["updated_at", "2024-07-18 14:21:20.154238"], ["state", "{\"hostname\":\"fv-az1149-759\",\"pid\":3685,\"proctitle\":\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/bin/rspec\",\"preserve_job_records\":true,\"retry_on_unhandled_error\":false,\"schedulers\":[],\"cron_enabled\":false,\"total_succeeded_executions_count\":0,\"total_errored_executions_count\":0,\"database_connection_pool\":{\"size\":20,\"active\":0}}"], ["lock_type", nil]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Load (0.5ms) 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" FROM "good_jobs" WHERE "good_jobs"."finished_at" IS NULL AND ("good_jobs"."scheduled_at" <= $1 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 $2) ORDER BY priority ASC NULLS LAST, "good_jobs"."created_at" ASC [["scheduled_at", "2024-07-18 14:21:20.155761"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Load (0.2ms) 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" = $1 LIMIT $2 [["id", "1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Execution Create (0.3ms) INSERT INTO "good_job_executions" ("created_at", "updated_at", "active_job_id", "job_class", "queue_name", "serialized_params", "scheduled_at", "finished_at", "error", "error_event", "error_backtrace", "process_id", "duration") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13) RETURNING "id" [["created_at", "2024-07-18 14:21:20.158097"], ["updated_at", "2024-07-18 14:21:20.158951"], ["active_job_id", "1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db"], ["job_class", "RetriedJob"], ["queue_name", "default"], ["serialized_params", "{\"job_id\":\"1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db\",\"locale\":\"en\",\"priority\":null,\"timezone\":\"UTC\",\"arguments\":[{\"_aj_globalid\":\"gid://test-app/GoodJob::Batch/948cd0fe-466c-46fb-87fa-781dbc82d451\"},{\"event\":{\"value\":\"finish\",\"_aj_serialized\":\"ActiveJob::Serializers::SymbolSerializer\"},\"_aj_symbol_keys\":[\"event\"]}],\"job_class\":\"RetriedJob\",\"executions\":0,\"queue_name\":\"default\",\"enqueued_at\":\"2024-07-18T14:21:20Z\",\"provider_job_id\":null,\"exception_executions\":{}}"], ["scheduled_at", "2024-07-18 14:21:20.123690"], ["finished_at", nil], ["error", nil], ["error_event", nil], ["error_backtrace", nil], ["process_id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["duration", nil]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update (0.3ms) UPDATE "good_jobs" SET "performed_at" = $1, "updated_at" = $2, "executions_count" = $3, "locked_by_id" = $4, "locked_at" = $5 WHERE "good_jobs"."id" = $6 [["performed_at", "2024-07-18 14:21:20.158097"], ["updated_at", "2024-07-18 14:21:20.160102"], ["executions_count", 1], ["locked_by_id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["locked_at", "2024-07-18 14:21:20.158395"], ["id", "1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db] GoodJob::BatchRecord Load (0.2ms) SELECT "good_job_batches".* FROM "good_job_batches" WHERE "good_job_batches"."id" = $1 LIMIT $2 [["id", "948cd0fe-466c-46fb-87fa-781dbc82d451"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db] Performing RetriedJob (Job ID: 1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db) from (default) enqueued at 2024-07-18T14:21:20Z with arguments: #>, {:event=>:finish} [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db] GoodJob::Job Update (0.3ms) UPDATE "good_jobs" SET "performed_at" = $1, "serialized_params" = $2, "scheduled_at" = $3, "created_at" = $4, "updated_at" = $5 WHERE "good_jobs"."id" = $6 [["performed_at", nil], ["serialized_params", "{\"job_class\":\"RetriedJob\",\"job_id\":\"1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db\",\"provider_job_id\":\"1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db\",\"queue_name\":\"default\",\"priority\":null,\"arguments\":[{\"_aj_globalid\":\"gid://test-app/GoodJob::Batch/948cd0fe-466c-46fb-87fa-781dbc82d451\"},{\"event\":{\"_aj_serialized\":\"ActiveJob::Serializers::SymbolSerializer\",\"value\":\"finish\"},\"_aj_symbol_keys\":[\"event\"]}],\"executions\":1,\"exception_executions\":{\"[\\\"RetryableError\\\"]\":1},\"locale\":\"en\",\"timezone\":\"UTC\",\"enqueued_at\":\"2024-07-18T14:21:20Z\"}"], ["scheduled_at", "2024-07-18 14:21:20.162555"], ["created_at", "2024-07-18 14:21:20.162706"], ["updated_at", "2024-07-18 14:21:20.163136"], ["id", "1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db"]] [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db] SQL (0.2ms) NOTIFY good_job, '{"queue_name":"default","scheduled_at":"2024-07-18T14:21:20.162Z"}' [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db] Enqueued RetriedJob (Job ID: 1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db) to (default) at 2024-07-18 14:21:20 UTC with arguments: #>, {:event=>:finish} [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db] Retrying RetriedJob in 0 seconds, due to a RetryableError. [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db] Performed RetriedJob (Job ID: 1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db) from (default) in 3.62ms [🐄 RSpec: calls success callbacks 🐄] [GoodJob] [3685] [RSpec: calls success callbacks] Executed GoodJob 1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Execution Update (0.6ms) UPDATE "good_job_executions" SET "updated_at" = $1, "finished_at" = $2, "error" = $3, "error_event" = $4, "error_backtrace" = $5, "duration" = $6 WHERE "good_job_executions"."id" = $7 [["updated_at", "2024-07-18 14:21:20.166107"], ["finished_at", "2024-07-18 14:21:20.165677"], ["error", "RetryableError: RetryableError"], ["error_event", 3], ["error_backtrace", "{\"/home/runner/work/good_job/good_job/spec/integration/batch_spec.rb:207:in `perform'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/execution.rb:65:in `block in _perform_job'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:118:in `block in run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/i18n-1.14.5/lib/i18n.rb:351:in `with_locale'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/translation.rb:9:in `block (2 levels) in '\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:127:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:127:in `block in run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/core_ext/time/zones.rb:65:in `use_zone'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/timezones.rb:9:in `block (2 levels) in '\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:127:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:127:in `block in run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:138:in `run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/execution.rb:64:in `_perform_job'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/instrumentation.rb:20:in `_perform_job'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/execution.rb:52:in `perform_now'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/instrumentation.rb:14:in `block in perform_now'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/instrumentation.rb:25:in `block in instrument'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/notifications.rb:206:in `block in instrument'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/notifications/instrumenter.rb:24:in `instrument'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/notifications.rb:206:in `instrument'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/instrumentation.rb:35:in `instrument'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/instrumentation.rb:14:in `perform_now'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/logging.rb:18:in `block in perform_now'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/tagged_logging.rb:99:in `block in tagged'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/tagged_logging.rb:37:in `tagged'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/tagged_logging.rb:99:in `tagged'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/logging.rb:25:in `tag_logger'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/logging.rb:18:in `perform_now'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/execution.rb:30:in `block in execute'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:118:in `block in run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/railtie.rb:54:in `block (4 levels) in '\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/execution_wrapper.rb:92:in `wrap'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/reloader.rb:72:in `block in wrap'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/execution_wrapper.rb:88:in `wrap'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/reloader.rb:71:in `wrap'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/railtie.rb:53:in `block (3 levels) in '\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:127:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:127:in `block in run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:138:in `run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activejob-7.0.8.4/lib/active_job/execution.rb:28:in `execute'\",\"/home/runner/work/good_job/good_job/app/models/good_job/job.rb:623:in `block (3 levels) in perform'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/notifications.rb:206:in `block in instrument'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/notifications/instrumenter.rb:24:in `instrument'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/notifications.rb:206:in `instrument'\",\"/home/runner/work/good_job/good_job/app/models/good_job/job.rb:622:in `block (2 levels) in perform'\",\"/home/runner/work/good_job/good_job/lib/good_job/current_thread.rb:113:in `within'\",\"/home/runner/work/good_job/good_job/app/models/good_job/job.rb:580:in `block in perform'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:118:in `block in run_callbacks'\",\"/home/runner/work/good_job/good_job/app/models/good_job/batch.rb:78:in `within_thread'\",\"/home/runner/work/good_job/good_job/app/models/good_job/job.rb:765:in `reset_batch_values'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:127:in `block in run_callbacks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/callbacks.rb:138:in `run_callbacks'\",\"/home/runner/work/good_job/good_job/app/models/good_job/job.rb:574:in `perform'\",\"/home/runner/work/good_job/good_job/app/models/good_job/job.rb:322:in `block in perform_with_advisory_lock'\",\"/home/runner/work/good_job/good_job/app/models/concerns/good_job/advisory_lockable.rb:172:in `block in with_advisory_lock'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation.rb:881:in `_scoping'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation.rb:428:in `scoping'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/scoping/default.rb:43:in `unscoped'\",\"/home/runner/work/good_job/good_job/app/models/concerns/good_job/advisory_lockable.rb:172:in `with_advisory_lock'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation/delegation.rb:67:in `block in with_advisory_lock'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation.rb:881:in `_scoping'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation.rb:428:in `scoping'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation/delegation.rb:67:in `with_advisory_lock'\",\"/home/runner/work/good_job/good_job/app/models/good_job/job.rb:316:in `perform_with_advisory_lock'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation/delegation.rb:67:in `block in perform_with_advisory_lock'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation.rb:881:in `_scoping'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation.rb:428:in `scoping'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activerecord-7.0.8.4/lib/active_record/relation/delegation.rb:67:in `perform_with_advisory_lock'\",\"/home/runner/work/good_job/good_job/lib/good_job/job_performer.rb:35:in `block in next'\",\"/home/runner/work/good_job/good_job/lib/good_job/capsule_tracker.rb:103:in `register'\",\"/home/runner/work/good_job/good_job/lib/good_job/job_performer.rb:34:in `next'\",\"/home/runner/work/good_job/good_job/lib/good_job.rb:261:in `block (2 levels) in perform_inline'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/execution_wrapper.rb:92:in `wrap'\",\"/home/runner/work/good_job/good_job/lib/good_job.rb:261:in `block in perform_inline'\",\"/home/runner/work/good_job/good_job/lib/good_job.rb:258:in `loop'\",\"/home/runner/work/good_job/good_job/lib/good_job.rb:258:in `perform_inline'\",\"/home/runner/work/good_job/good_job/spec/integration/batch_spec.rb:231:in `block (3 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:263:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:263:in `block in run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:511:in `block in with_around_and_singleton_context_hooks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:468:in `block in with_around_example_hooks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:486:in `block in run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:626:in `block in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-rails-6.1.3/lib/rspec/rails/adapters.rb:75:in `block (2 levels) in '\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:390:in `execute_with'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/spec/support/reset_rails_queue_adapter.rb:27:in `block (2 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:390:in `execute_with'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/spec/support/reset_good_job.rb:29:in `block (2 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:390:in `execute_with'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/spec/support/rails_executor.rb:19:in `block (3 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/activesupport-7.0.8.4/lib/active_support/execution_wrapper.rb:105:in `perform'\",\"/home/runner/work/good_job/good_job/spec/support/rails_executor.rb:17:in `block (2 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:390:in `execute_with'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/spec/support/postgres_notices.rb:33:in `block (2 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:390:in `execute_with'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/spec/support/logger.rb:7:in `block (2 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:390:in `execute_with'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/spec/support/database_cleaner.rb:17:in `block (2 levels) in
'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:457:in `instance_exec'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:390:in `execute_with'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:628:in `block (2 levels) in run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:352:in `call'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:629:in `run_around_example_hooks_for'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/hooks.rb:486:in `run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:468:in `with_around_example_hooks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:511:in `with_around_and_singleton_context_hooks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example.rb:259:in `run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example_group.rb:646:in `block in run_examples'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example_group.rb:642:in `map'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example_group.rb:642:in `run_examples'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example_group.rb:607:in `run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example_group.rb:608:in `block in run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example_group.rb:608:in `map'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/example_group.rb:608:in `run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:121:in `block (3 levels) in run_specs'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:121:in `map'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:121:in `block (2 levels) in run_specs'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/configuration.rb:2091:in `with_suite_hooks'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:116:in `block in run_specs'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/reporter.rb:74:in `report'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:115:in `run_specs'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:89:in `run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:71:in `run'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/lib/rspec/core/runner.rb:45:in `invoke'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/gems/rspec-core-3.13.0/exe/rspec:4:in `'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/bin/rspec:25:in `load'\",\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/bin/rspec:25:in `'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli/exec.rb:58:in `load'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli/exec.rb:58:in `kernel_load'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli/exec.rb:23:in `run'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli.rb:479:in `exec'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor/command.rb:27:in `run'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor/invocation.rb:127:in `invoke_command'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor.rb:392:in `dispatch'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli.rb:31:in `dispatch'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/vendor/thor/lib/thor/base.rb:485:in `start'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/cli.rb:25:in `start'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/exe/bundle:49:in `block in '\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/lib/bundler/friendly_errors.rb:103:in `with_friendly_errors'\",\"/home/runner/work/good_job/good_job/vendor/bundle/ruby/3.0.0/gems/bundler-2.2.33/exe/bundle:37:in `'\",\"/opt/hostedtoolcache/Ruby/3.0.7/x64/bin/bundle:25:in `load'\",\"/opt/hostedtoolcache/Ruby/3.0.7/x64/bin/bundle:25:in `
'\"}"], ["duration", "PT0.00758142099999759S"], ["id", "79ec1c45-5786-4734-895e-640041a4e55f"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update (0.3ms) UPDATE "good_jobs" SET "locked_by_id" = $1, "locked_at" = $2, "error" = $3, "updated_at" = $4, "error_event" = $5 WHERE "good_jobs"."id" = $6 [["locked_by_id", nil], ["locked_at", nil], ["error", "RetryableError: RetryableError"], ["updated_at", "2024-07-18 14:21:20.168380"], ["error_event", 3], ["id", "1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] GoodJob::Lockable Advisory Unlock (0.2ms) SELECT pg_advisory_unlock(('x'||substr(md5($1::text), 1, 16))::bit(64)::bigint) AS unlocked [["key", "good_jobs-1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Process Destroy (0.2ms) DELETE FROM "good_job_processes" WHERE "good_job_processes"."id" = $1 [["id", "664c4bd6-5530-4316-954a-f4604477fc1c"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update All (0.2ms) UPDATE "good_jobs" SET "locked_by_id" = $1 WHERE "good_jobs"."locked_by_id" = $2 [["locked_by_id", nil], ["locked_by_id", "664c4bd6-5530-4316-954a-f4604477fc1c"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] (0.3ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐄 RSpec: calls success callbacks 🐄] Connection returned to pool with 2 advisory locks [🐄 RSpec: calls success callbacks 🐄] Set application name (0.2ms) SET application_name = 'RSpec: calls success callbacks' [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Process Create (0.2ms) INSERT INTO "good_job_processes" ("id", "created_at", "updated_at", "state", "lock_type") VALUES ($1, $2, $3, $4, $5) RETURNING "id" [["id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["created_at", "2024-07-18 14:21:20.173125"], ["updated_at", "2024-07-18 14:21:20.173125"], ["state", "{\"hostname\":\"fv-az1149-759\",\"pid\":3685,\"proctitle\":\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/bin/rspec\",\"preserve_job_records\":true,\"retry_on_unhandled_error\":false,\"schedulers\":[],\"cron_enabled\":false,\"total_succeeded_executions_count\":0,\"total_errored_executions_count\":0,\"database_connection_pool\":{\"size\":20,\"active\":0}}"], ["lock_type", nil]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Load (0.5ms) 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" FROM "good_jobs" WHERE "good_jobs"."finished_at" IS NULL AND ("good_jobs"."scheduled_at" <= $1 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 $2) ORDER BY priority ASC NULLS LAST, "good_jobs"."created_at" ASC [["scheduled_at", "2024-07-18 14:21:20.174642"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Load (0.2ms) 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" = $1 LIMIT $2 [["id", "0d10e67f-c5d9-4643-956a-84a7ea62e09e"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Execution Create (0.3ms) INSERT INTO "good_job_executions" ("created_at", "updated_at", "active_job_id", "job_class", "queue_name", "serialized_params", "scheduled_at", "finished_at", "error", "error_event", "error_backtrace", "process_id", "duration") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13) RETURNING "id" [["created_at", "2024-07-18 14:21:20.176648"], ["updated_at", "2024-07-18 14:21:20.177667"], ["active_job_id", "0d10e67f-c5d9-4643-956a-84a7ea62e09e"], ["job_class", "RetriedJob"], ["queue_name", "default"], ["serialized_params", "{\"job_id\":\"0d10e67f-c5d9-4643-956a-84a7ea62e09e\",\"locale\":\"en\",\"priority\":null,\"timezone\":\"UTC\",\"arguments\":[{\"_aj_globalid\":\"gid://test-app/GoodJob::Batch/948cd0fe-466c-46fb-87fa-781dbc82d451\"},{\"event\":{\"value\":\"success\",\"_aj_serialized\":\"ActiveJob::Serializers::SymbolSerializer\"},\"_aj_symbol_keys\":[\"event\"]}],\"job_class\":\"RetriedJob\",\"executions\":1,\"queue_name\":\"default\",\"enqueued_at\":\"2024-07-18T14:21:20Z\",\"provider_job_id\":\"0d10e67f-c5d9-4643-956a-84a7ea62e09e\",\"exception_executions\":{\"[\\\"RetryableError\\\"]\":1}}"], ["scheduled_at", "2024-07-18 14:21:20.137917"], ["finished_at", nil], ["error", nil], ["error_event", nil], ["error_backtrace", nil], ["process_id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["duration", nil]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update (0.3ms) UPDATE "good_jobs" SET "performed_at" = $1, "updated_at" = $2, "executions_count" = $3, "locked_by_id" = $4, "locked_at" = $5 WHERE "good_jobs"."id" = $6 [["performed_at", "2024-07-18 14:21:20.176648"], ["updated_at", "2024-07-18 14:21:20.178823"], ["executions_count", 2], ["locked_by_id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["locked_at", "2024-07-18 14:21:20.176943"], ["id", "0d10e67f-c5d9-4643-956a-84a7ea62e09e"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [0d10e67f-c5d9-4643-956a-84a7ea62e09e] GoodJob::BatchRecord Load (0.2ms) SELECT "good_job_batches".* FROM "good_job_batches" WHERE "good_job_batches"."id" = $1 LIMIT $2 [["id", "948cd0fe-466c-46fb-87fa-781dbc82d451"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [0d10e67f-c5d9-4643-956a-84a7ea62e09e] Performing RetriedJob (Job ID: 0d10e67f-c5d9-4643-956a-84a7ea62e09e) from (default) enqueued at 2024-07-18T14:21:20Z with arguments: #>, {:event=>:success} [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [0d10e67f-c5d9-4643-956a-84a7ea62e09e] Performed RetriedJob (Job ID: 0d10e67f-c5d9-4643-956a-84a7ea62e09e) from (default) in 0.82ms [🐄 RSpec: calls success callbacks 🐄] [GoodJob] [3685] [RSpec: calls success callbacks] Executed GoodJob 0d10e67f-c5d9-4643-956a-84a7ea62e09e [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Execution Update (0.2ms) UPDATE "good_job_executions" SET "updated_at" = $1, "finished_at" = $2, "duration" = $3 WHERE "good_job_executions"."id" = $4 [["updated_at", "2024-07-18 14:21:20.181681"], ["finished_at", "2024-07-18 14:21:20.181210"], ["duration", "PT0.004564439999967362S"], ["id", "5a15e16d-1abc-464c-9445-e19e89c4f2d9"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update (0.3ms) UPDATE "good_jobs" SET "locked_by_id" = $1, "locked_at" = $2, "finished_at" = $3, "error" = $4, "updated_at" = $5, "error_event" = $6 WHERE "good_jobs"."id" = $7 [["locked_by_id", nil], ["locked_at", nil], ["finished_at", "2024-07-18 14:21:20.181210"], ["error", nil], ["updated_at", "2024-07-18 14:21:20.182554"], ["error_event", nil], ["id", "0d10e67f-c5d9-4643-956a-84a7ea62e09e"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] GoodJob::Lockable Advisory Unlock (0.2ms) SELECT pg_advisory_unlock(('x'||substr(md5($1::text), 1, 16))::bit(64)::bigint) AS unlocked [["key", "good_jobs-0d10e67f-c5d9-4643-956a-84a7ea62e09e"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Process Destroy (0.2ms) DELETE FROM "good_job_processes" WHERE "good_job_processes"."id" = $1 [["id", "664c4bd6-5530-4316-954a-f4604477fc1c"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update All (0.3ms) UPDATE "good_jobs" SET "locked_by_id" = $1 WHERE "good_jobs"."locked_by_id" = $2 [["locked_by_id", nil], ["locked_by_id", "664c4bd6-5530-4316-954a-f4604477fc1c"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] (0.3ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐄 RSpec: calls success callbacks 🐄] Connection returned to pool with 2 advisory locks [🐄 RSpec: calls success callbacks 🐄] Set application name (0.2ms) SET application_name = 'RSpec: calls success callbacks' [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Process Create (0.2ms) INSERT INTO "good_job_processes" ("id", "created_at", "updated_at", "state", "lock_type") VALUES ($1, $2, $3, $4, $5) RETURNING "id" [["id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["created_at", "2024-07-18 14:21:20.187481"], ["updated_at", "2024-07-18 14:21:20.187481"], ["state", "{\"hostname\":\"fv-az1149-759\",\"pid\":3685,\"proctitle\":\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/bin/rspec\",\"preserve_job_records\":true,\"retry_on_unhandled_error\":false,\"schedulers\":[],\"cron_enabled\":false,\"total_succeeded_executions_count\":0,\"total_errored_executions_count\":0,\"database_connection_pool\":{\"size\":20,\"active\":0}}"], ["lock_type", nil]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Load (0.5ms) 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" FROM "good_jobs" WHERE "good_jobs"."finished_at" IS NULL AND ("good_jobs"."scheduled_at" <= $1 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 $2) ORDER BY priority ASC NULLS LAST, "good_jobs"."created_at" ASC [["scheduled_at", "2024-07-18 14:21:20.188997"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Load (0.3ms) 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" = $1 LIMIT $2 [["id", "1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Execution Create (0.3ms) INSERT INTO "good_job_executions" ("created_at", "updated_at", "active_job_id", "job_class", "queue_name", "serialized_params", "scheduled_at", "finished_at", "error", "error_event", "error_backtrace", "process_id", "duration") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13) RETURNING "id" [["created_at", "2024-07-18 14:21:20.191249"], ["updated_at", "2024-07-18 14:21:20.192089"], ["active_job_id", "1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db"], ["job_class", "RetriedJob"], ["queue_name", "default"], ["serialized_params", "{\"job_id\":\"1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db\",\"locale\":\"en\",\"priority\":null,\"timezone\":\"UTC\",\"arguments\":[{\"_aj_globalid\":\"gid://test-app/GoodJob::Batch/948cd0fe-466c-46fb-87fa-781dbc82d451\"},{\"event\":{\"value\":\"finish\",\"_aj_serialized\":\"ActiveJob::Serializers::SymbolSerializer\"},\"_aj_symbol_keys\":[\"event\"]}],\"job_class\":\"RetriedJob\",\"executions\":1,\"queue_name\":\"default\",\"enqueued_at\":\"2024-07-18T14:21:20Z\",\"provider_job_id\":\"1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db\",\"exception_executions\":{\"[\\\"RetryableError\\\"]\":1}}"], ["scheduled_at", "2024-07-18 14:21:20.162555"], ["finished_at", nil], ["error", nil], ["error_event", nil], ["error_backtrace", nil], ["process_id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["duration", nil]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update (0.3ms) UPDATE "good_jobs" SET "performed_at" = $1, "updated_at" = $2, "executions_count" = $3, "locked_by_id" = $4, "locked_at" = $5 WHERE "good_jobs"."id" = $6 [["performed_at", "2024-07-18 14:21:20.191249"], ["updated_at", "2024-07-18 14:21:20.193237"], ["executions_count", 2], ["locked_by_id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["locked_at", "2024-07-18 14:21:20.191550"], ["id", "1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db] GoodJob::BatchRecord Load (0.2ms) SELECT "good_job_batches".* FROM "good_job_batches" WHERE "good_job_batches"."id" = $1 LIMIT $2 [["id", "948cd0fe-466c-46fb-87fa-781dbc82d451"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db] Performing RetriedJob (Job ID: 1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db) from (default) enqueued at 2024-07-18T14:21:20Z with arguments: #>, {:event=>:finish} [🐄 RSpec: calls success callbacks 🐄] [ActiveJob] [RetriedJob] [1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db] Performed RetriedJob (Job ID: 1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db) from (default) in 0.67ms [🐄 RSpec: calls success callbacks 🐄] [GoodJob] [3685] [RSpec: calls success callbacks] Executed GoodJob 1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Execution Update (0.2ms) UPDATE "good_job_executions" SET "updated_at" = $1, "finished_at" = $2, "duration" = $3 WHERE "good_job_executions"."id" = $4 [["updated_at", "2024-07-18 14:21:20.196120"], ["finished_at", "2024-07-18 14:21:20.195633"], ["duration", "PT0.004385445000025356S"], ["id", "a3a9880d-e27f-482f-8abd-471b84e9772d"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update (0.3ms) UPDATE "good_jobs" SET "locked_by_id" = $1, "locked_at" = $2, "finished_at" = $3, "error" = $4, "updated_at" = $5, "error_event" = $6 WHERE "good_jobs"."id" = $7 [["locked_by_id", nil], ["locked_at", nil], ["finished_at", "2024-07-18 14:21:20.195633"], ["error", nil], ["updated_at", "2024-07-18 14:21:20.196995"], ["error_event", nil], ["id", "1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] GoodJob::Lockable Advisory Unlock (0.2ms) SELECT pg_advisory_unlock(('x'||substr(md5($1::text), 1, 16))::bit(64)::bigint) AS unlocked [["key", "good_jobs-1c0cd1e7-3ca2-48b4-8ad2-4d7dfd25d6db"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Process Destroy (0.2ms) DELETE FROM "good_job_processes" WHERE "good_job_processes"."id" = $1 [["id", "664c4bd6-5530-4316-954a-f4604477fc1c"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update All (0.2ms) UPDATE "good_jobs" SET "locked_by_id" = $1 WHERE "good_jobs"."locked_by_id" = $2 [["locked_by_id", nil], ["locked_by_id", "664c4bd6-5530-4316-954a-f4604477fc1c"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] (0.3ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐄 RSpec: calls success callbacks 🐄] Connection returned to pool with 2 advisory locks [🐄 RSpec: calls success callbacks 🐄] Set application name (0.2ms) SET application_name = 'RSpec: calls success callbacks' [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Process Create (0.2ms) INSERT INTO "good_job_processes" ("id", "created_at", "updated_at", "state", "lock_type") VALUES ($1, $2, $3, $4, $5) RETURNING "id" [["id", "664c4bd6-5530-4316-954a-f4604477fc1c"], ["created_at", "2024-07-18 14:21:20.201957"], ["updated_at", "2024-07-18 14:21:20.201957"], ["state", "{\"hostname\":\"fv-az1149-759\",\"pid\":3685,\"proctitle\":\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.0.0/bin/rspec\",\"preserve_job_records\":true,\"retry_on_unhandled_error\":false,\"schedulers\":[],\"cron_enabled\":false,\"total_succeeded_executions_count\":0,\"total_errored_executions_count\":0,\"database_connection_pool\":{\"size\":20,\"active\":0}}"], ["lock_type", nil]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Load (0.5ms) 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" FROM "good_jobs" WHERE "good_jobs"."finished_at" IS NULL AND ("good_jobs"."scheduled_at" <= $1 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 $2) ORDER BY priority ASC NULLS LAST, "good_jobs"."created_at" ASC [["scheduled_at", "2024-07-18 14:21:20.203609"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.1ms) BEGIN [🐄 RSpec: calls success callbacks 🐄] GoodJob::Process Destroy (0.2ms) DELETE FROM "good_job_processes" WHERE "good_job_processes"."id" = $1 [["id", "664c4bd6-5530-4316-954a-f4604477fc1c"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Update All (0.2ms) UPDATE "good_jobs" SET "locked_by_id" = $1 WHERE "good_jobs"."locked_by_id" = $2 [["locked_by_id", nil], ["locked_by_id", "664c4bd6-5530-4316-954a-f4604477fc1c"]] [🐄 RSpec: calls success callbacks 🐄] TRANSACTION (0.3ms) COMMIT [🐄 RSpec: calls success callbacks 🐄] (0.3ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐄 RSpec: calls success callbacks 🐄] Connection returned to pool with 2 advisory locks [🐄 RSpec: calls success callbacks 🐄] Set application name (0.2ms) SET application_name = 'RSpec: calls success callbacks' [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Count (0.2ms) SELECT COUNT(*) FROM "good_jobs" [🐄 RSpec: calls success callbacks 🐄] GoodJob::Execution Count (0.2ms) SELECT COUNT(*) FROM "good_job_executions" [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Count (0.2ms) SELECT COUNT(*) FROM "good_jobs" WHERE "good_jobs"."batch_id" = $1 [["batch_id", "948cd0fe-466c-46fb-87fa-781dbc82d451"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Count (0.3ms) SELECT COUNT(*) FROM "good_jobs" WHERE "good_jobs"."batch_callback_id" = $1 [["batch_callback_id", "948cd0fe-466c-46fb-87fa-781dbc82d451"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Load (0.2ms) 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"."batch_callback_id" = $1 [["batch_callback_id", "948cd0fe-466c-46fb-87fa-781dbc82d451"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::BatchRecord Load (0.2ms) SELECT "good_job_batches".* FROM "good_job_batches" WHERE "good_job_batches"."id" = $1 LIMIT $2 [["id", "948cd0fe-466c-46fb-87fa-781dbc82d451"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] CACHE GoodJob::BatchRecord Load (0.0ms) SELECT "good_job_batches".* FROM "good_job_batches" WHERE "good_job_batches"."id" = $1 LIMIT $2 [["id", "948cd0fe-466c-46fb-87fa-781dbc82d451"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] PgLock Exists? (0.4ms) SELECT 1 AS one FROM "pg_locks" JOIN pg_database ON pg_database.oid = pg_locks.database WHERE (pg_database.datname = current_database()) AND "pg_locks"."locktype" = $1 AND (pid = pg_backend_pid()) LIMIT $2 [["locktype", "advisory"], ["LIMIT", 1]] [🐄 RSpec: calls success callbacks 🐄] PgLock Count (0.4ms) SELECT COUNT(*) FROM "pg_locks" JOIN pg_database ON pg_database.oid = pg_locks.database WHERE (pg_database.datname = current_database()) AND "pg_locks"."locktype" = $1 AND (pid = pg_backend_pid()) [["locktype", "advisory"]] [🐄 RSpec: calls success callbacks 🐄] GoodJob::Job Load (0.8ms) 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" 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"."id"::text), 1, 16))::bit(32)::int AND pg_locks.objid = (('x' || substr(md5('good_jobs' || '-' || "good_jobs"."id"::text), 1, 16))::bit(64) << 32)::bit(32)::int WHERE "pg_locks"."locktype" IS NOT NULL AND ("pg_locks"."pid" = pg_backend_pid()) [🐄 RSpec: calls success callbacks 🐄] PgLock Load (0.4ms) SELECT "pg_locks".* FROM "pg_locks" JOIN pg_database ON pg_database.oid = pg_locks.database WHERE (pg_database.datname = current_database()) AND "pg_locks"."locktype" = $1 AND (pid = pg_backend_pid()) [["locktype", "advisory"]] [🐄 RSpec: calls success callbacks 🐄] PgStatActivity Load (0.4ms) SELECT "pg_stat_activity".* FROM "pg_stat_activity" WHERE "pg_stat_activity"."pid" = $1 [["pid", 1057]] [🐄 RSpec: calls success callbacks 🐄] PgStatActivity Load (0.7ms) SELECT "pg_stat_activity".* FROM "pg_stat_activity" [🐄 RSpec: calls success callbacks 🐄] CACHE PgLock Count (0.0ms) SELECT COUNT(*) FROM "pg_locks" JOIN pg_database ON pg_database.oid = pg_locks.database WHERE (pg_database.datname = current_database()) AND "pg_locks"."locktype" = $1 AND (pid = pg_backend_pid()) [["locktype", "advisory"]] [🐄 RSpec: calls success callbacks 🐄] (0.4ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐄 RSpec: calls success callbacks 🐄] Connection returned to pool with 2 advisory locks [🐄 RSpec: calls success callbacks 🐄] ---- START EXAMPLE: Batches all callbacks are called and retryable calls discard callbacks (./spec/integration/batch_spec.rb:212) [🐌 RSpec: calls discard callbacks 🐌] Set application name (0.2ms) SET application_name = 'RSpec: calls discard callbacks' [🐌 RSpec: calls discard callbacks 🐌] PgLock Count (0.3ms) SELECT COUNT(*) FROM "pg_locks" WHERE "pg_locks"."locktype" = $1 AND (pid = pg_backend_pid()) [["locktype", "advisory"]] [🐌 RSpec: calls discard callbacks 🐌] PgLock Load (0.4ms) SELECT "pg_locks".* FROM "pg_locks" JOIN pg_database ON pg_database.oid = pg_locks.database WHERE (pg_database.datname = current_database()) AND "pg_locks"."locktype" = $1 AND (pid = pg_backend_pid()) [["locktype", "advisory"]] [🐌 RSpec: calls discard callbacks 🐌] PgLock Advisory Unlock (0.3ms) SELECT pg_advisory_unlock(($1::bigint << 32) + $2::bigint) AS unlocked [["classid", "2106745852"], ["objid", "2595676620"]] [🐌 RSpec: calls discard callbacks 🐌] PgLock Advisory Unlock (0.2ms) SELECT pg_advisory_unlock(($1::bigint << 32) + $2::bigint) AS unlocked [["classid", "1392869571"], ["objid", "4037851334"]] [🐌 RSpec: calls discard callbacks 🐌] PgLock Count (0.3ms) SELECT COUNT(*) FROM "pg_locks" WHERE "pg_locks"."locktype" = $1 AND (pid != pg_backend_pid()) [["locktype", "advisory"]] [🐌 RSpec: calls discard callbacks 🐌] PgLock Count (0.3ms) SELECT COUNT(*) FROM "pg_locks" JOIN pg_database ON pg_database.oid = pg_locks.database WHERE (pg_database.datname = current_database()) AND "pg_locks"."locktype" = $1 [["locktype", "advisory"]] [🐌 RSpec: calls discard callbacks 🐌] (0.3ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐌 RSpec: calls discard callbacks 🐌] Connection returned to pool with 2 advisory locks [🐌 RSpec: calls discard callbacks 🐌] ---- START EXAMPLE: Batches complex recursive batching can enqueue multiple jobs (./spec/integration/batch_spec.rb:178) [🐫 RSpec: can enqueue multiple jobs 🐫] Set application name (0.2ms) SET application_name = 'RSpec: can enqueue multiple jobs' [🐫 RSpec: can enqueue multiple jobs 🐫] PgLock Count (0.3ms) SELECT COUNT(*) FROM "pg_locks" WHERE "pg_locks"."locktype" = $1 AND (pid = pg_backend_pid()) [["locktype", "advisory"]] [🐫 RSpec: can enqueue multiple jobs 🐫] PgLock Load (0.6ms) SELECT "pg_locks".* FROM "pg_locks" JOIN pg_database ON pg_database.oid = pg_locks.database WHERE (pg_database.datname = current_database()) AND "pg_locks"."locktype" = $1 AND (pid = pg_backend_pid()) [["locktype", "advisory"]] [🐫 RSpec: can enqueue multiple jobs 🐫] PgLock Advisory Unlock (0.2ms) SELECT pg_advisory_unlock(($1::bigint << 32) + $2::bigint) AS unlocked [["classid", "2106745852"], ["objid", "2595676620"]] [🐫 RSpec: can enqueue multiple jobs 🐫] PgLock Advisory Unlock (0.2ms) SELECT pg_advisory_unlock(($1::bigint << 32) + $2::bigint) AS unlocked [["classid", "1392869571"], ["objid", "4037851334"]] [🐫 RSpec: can enqueue multiple jobs 🐫] PgLock Count (0.3ms) SELECT COUNT(*) FROM "pg_locks" WHERE "pg_locks"."locktype" = $1 AND (pid != pg_backend_pid()) [["locktype", "advisory"]] [🐫 RSpec: can enqueue multiple jobs 🐫] PgLock Count (0.4ms) SELECT COUNT(*) FROM "pg_locks" JOIN pg_database ON pg_database.oid = pg_locks.database WHERE (pg_database.datname = current_database()) AND "pg_locks"."locktype" = $1 [["locktype", "advisory"]] [🐫 RSpec: can enqueue multiple jobs 🐫] (0.3ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐫 RSpec: can enqueue multiple jobs 🐫] Connection returned to pool with 2 advisory locks [🐫 RSpec: can enqueue multiple jobs 🐫] ---- START EXAMPLE: Batches simple batching assigns a batch_id to all jobs in the batch (./spec/integration/batch_spec.rb:29) ```
bensheldon commented 2 months ago

Another Flake, in a different spot:

  .perform_inline
    RUNNING: executes performable jobs
    executes performable jobs
    RUNNING: executes future scheduled jobs
    executes future scheduled jobs
    RUNNING: can accept a limit
Connection returned to pool with 1 advisory locks
There are 1 advisory locks still open by the current database connection AFTER test run.

Advisory locked executions:
  - Execution ID: 826fca11-5f34-44a1-a8c0-42f582b38b7b / Active Job ID: 826fca11-5f34-44a1-a8c0-42f582b38b7b

Advisory Locks:
  - 1027: RSpec: can accept a limit

Current connections:
  - 67: 
  - 68: 
  - 1027: RSpec: can accept a limit
  - 64: 
  - 63: 
  - 66: 
Connection returned to pool with 1 advisory locks
    can accept a limit (FAILED - 1)

  1) GoodJob.perform_inline can accept a limit
     Got 2 failures:

     1.1) Failure/Error: expect(PgLock.current_database.advisory_lock.owns.count).to eq(0), "Existing owned advisory locks AFTER test run"
            Existing owned advisory locks AFTER test run
          # ./spec/support/reset_good_job.rb:92:in `block (2 levels) in <main>'
          # ./spec/support/reset_rails_queue_adapter.rb:27:in `block (2 levels) in <main>'
          # ./spec/support/reset_good_job.rb:29:in `block (2 levels) in <main>'
          # ./spec/support/rails_executor.rb:19:in `block (3 levels) in <main>'
          # ./spec/support/rails_executor.rb:17:in `block (2 levels) in <main>'
          # ./spec/support/postgres_notices.rb:33:in `block (2 levels) in <main>'
          # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
          # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'

     1.2) Failure/Error: expect(POSTGRES_NOTICES).to be_empty
            expected `["Connection returned to pool with 1 advisory locks", "Connection returned to pool with 1 advisory locks"].empty?` to be truthy, got false
          # ./spec/support/postgres_notices.rb:34:in `block (2 levels) in <main>'
          # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
          # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'
    RUNNING: raises unhandled exceptions
Connection returned to pool with 1 advisory locks
Connection returned to pool with 2 advisory locks
There are 2 advisory locks still open by the current database connection AFTER test run.

Advisory locked executions:
  - Execution ID: 09732317-0853-46e6-87ca-de74172bb82b / Active Job ID: 09732317-0853-46e6-87ca-de74172bb82b
  - Execution ID: 97e5f1d7-9b1e-4c93-817f-c03a3083886f / Active Job ID: 97e5f1d7-9b1e-4c93-817f-c03a3083886f

Advisory Locks:
  - 1027: RSpec: raises unhandled exceptions
  - 1027: RSpec: raises unhandled exceptions

Current connections:
  - 67: 
  - 68: 
  - 1027: RSpec: raises unhandled exceptions
  - 64: 
  - 63: 
  - 66: 
Connection returned to pool with 2 advisory locks
    raises unhandled exceptions (FAILED - 2)

  2) GoodJob.perform_inline raises unhandled exceptions
     Got 2 failures:

     2.1) Failure/Error: expect(PgLock.current_database.advisory_lock.owns.count).to eq(0), "Existing owned advisory locks AFTER test run"
            Existing owned advisory locks AFTER test run
          # ./spec/support/reset_good_job.rb:92:in `block (2 levels) in <main>'
          # ./spec/support/reset_rails_queue_adapter.rb:27:in `block (2 levels) in <main>'
          # ./spec/support/reset_good_job.rb:29:in `block (2 levels) in <main>'
          # ./spec/support/rails_executor.rb:19:in `block (3 levels) in <main>'
          # ./spec/support/rails_executor.rb:17:in `block (2 levels) in <main>'
          # ./spec/support/postgres_notices.rb:33:in `block (2 levels) in <main>'
          # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
          # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'

     2.2) Failure/Error: expect(POSTGRES_NOTICES).to be_empty
            expected `["Connection returned to pool with 1 advisory locks", "Connection returned to pool with 2 advisory locks", "Connection returned to pool with 2 advisory locks"].empty?` to be truthy, got false
          # ./spec/support/postgres_notices.rb:34:in `block (2 levels) in <main>'
          # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
          # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'
  .shutdown?
    RUNNING: returns whether any capsules are running
Connection returned to pool with 2 advisory locks
    returns whether any capsules are running (FAILED - 3)

  3) GoodJob.shutdown? returns whether any capsules are running
     Failure/Error: expect(PgLock.current_database.advisory_lock.count).to eq(0), "Existing advisory locks BEFORE test run"
       Existing advisory locks BEFORE test run
     # ./spec/support/reset_good_job.rb:21:in `block (2 levels) in <main>'
     # ./spec/support/rails_executor.rb:19:in `block (3 levels) in <main>'
     # ./spec/support/rails_executor.rb:17:in `block (2 levels) in <main>'
     # ./spec/support/postgres_notices.rb:33:in `block (2 levels) in <main>'
     # ./spec/support/logger.rb:7:in `block (2 levels) in <main>'
     # ./spec/support/database_cleaner.rb:17:in `block (2 levels) in <main>'
  .restart
    RUNNING: does nothing when there are no capsule instances
    does nothing when there are no capsule instances
    RUNNING: restarts all capsule instances
    restarts all capsule instances
    when in webserver but not in async mode
      RUNNING: does not start capsules
      does not start capsules
  .cleanup_preserved_jobs
    RUNNING: deletes finished jobs
    deletes finished jobs
    RUNNING: takes arguments
    takes arguments
    RUNNING: is instrumented
    is instrumented
    RUNNING: respects the cleanup_discarded_jobs? configuration
    respects the cleanup_discarded_jobs? configuration
bensheldon commented 2 months ago
Log messages ``` [🐾 RSpec: executes future scheduled jobs 🐾] (0.4ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐾 RSpec: executes future scheduled jobs 🐾] TRANSACTION (0.1ms) BEGIN [🐾 RSpec: executes future scheduled jobs 🐾] (0.4ms) ALTER TABLE "schema_migrations" DISABLE TRIGGER ALL;ALTER TABLE "ar_internal_metadata" DISABLE TRIGGER ALL;ALTER TABLE "good_job_processes" DISABLE TRIGGER ALL;ALTER TABLE "good_job_batches" DISABLE TRIGGER ALL;ALTER TABLE "good_job_settings" DISABLE TRIGGER ALL;ALTER TABLE "good_job_executions" DISABLE TRIGGER ALL;ALTER TABLE "good_jobs" DISABLE TRIGGER ALL [🐾 RSpec: executes future scheduled jobs 🐾] TRANSACTION (0.1ms) COMMIT [🐾 RSpec: executes future scheduled jobs 🐾] (21.4ms) TRUNCATE TABLE "good_job_processes", "good_job_batches", "good_job_settings", "good_job_executions", "good_jobs" [🐾 RSpec: executes future scheduled jobs 🐾] TRANSACTION (0.2ms) BEGIN [🐾 RSpec: executes future scheduled jobs 🐾] (0.3ms) ALTER TABLE "schema_migrations" ENABLE TRIGGER ALL;ALTER TABLE "ar_internal_metadata" ENABLE TRIGGER ALL;ALTER TABLE "good_job_processes" ENABLE TRIGGER ALL;ALTER TABLE "good_job_batches" ENABLE TRIGGER ALL;ALTER TABLE "good_job_settings" ENABLE TRIGGER ALL;ALTER TABLE "good_job_executions" ENABLE TRIGGER ALL;ALTER TABLE "good_jobs" ENABLE TRIGGER ALL [🐾 RSpec: executes future scheduled jobs 🐾] TRANSACTION (0.1ms) COMMIT [🐾 RSpec: executes future scheduled jobs 🐾] (0.7ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐾 RSpec: executes future scheduled jobs 🐾] ---- START EXAMPLE: GoodJob.perform_inline can accept a limit (./spec/lib/good_job_spec.rb:156) [🐤 RSpec: can accept a limit 🐤] PgLock Count (0.6ms) SELECT COUNT(*) FROM "pg_locks" WHERE "pg_locks"."locktype" = $1 AND (pid = pg_backend_pid()) [["locktype", "advisory"]] [🐤 RSpec: can accept a limit 🐤] PgLock Count (0.3ms) SELECT COUNT(*) FROM "pg_locks" WHERE "pg_locks"."locktype" = $1 AND (pid != pg_backend_pid()) [["locktype", "advisory"]] [🐤 RSpec: can accept a limit 🐤] PgLock Count (0.4ms) SELECT COUNT(*) FROM "pg_locks" JOIN pg_database ON pg_database.oid = pg_locks.database WHERE (pg_database.datname = current_database()) AND "pg_locks"."locktype" = $1 [["locktype", "advisory"]] [🐤 RSpec: can accept a limit 🐤] [ActiveJob] TRANSACTION (0.2ms) BEGIN [🐤 RSpec: can accept a limit 🐤] [ActiveJob] GoodJob::Job Create (1.2ms) INSERT INTO "good_jobs" ("id", "queue_name", "priority", "serialized_params", "scheduled_at", "performed_at", "finished_at", "error", "created_at", "updated_at", "active_job_id", "concurrency_key", "cron_key", "cron_at", "batch_id", "batch_callback_id", "executions_count", "job_class", "error_event", "labels", "locked_by_id", "locked_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16, $17, $18, $19, $20, $21, $22) RETURNING "id" [["id", "826fca11-5f34-44a1-a8c0-42f582b38b7b"], ["queue_name", "default"], ["priority", 0], ["serialized_params", "{\"job_class\":\"TestJob\",\"job_id\":\"826fca11-5f34-44a1-a8c0-42f582b38b7b\",\"provider_job_id\":null,\"queue_name\":\"default\",\"priority\":null,\"arguments\":[],\"executions\":0,\"exception_executions\":{},\"locale\":\"en\",\"timezone\":\"UTC\",\"enqueued_at\":\"2024-07-18T15:43:21.414061913Z\",\"scheduled_at\":null}"], ["scheduled_at", "2024-07-18 15:43:21.414083"], ["performed_at", nil], ["finished_at", nil], ["error", nil], ["created_at", "2024-07-18 15:43:21.414083"], ["updated_at", "2024-07-18 15:43:21.414759"], ["active_job_id", "826fca11-5f34-44a1-a8c0-42f582b38b7b"], ["concurrency_key", nil], ["cron_key", nil], ["cron_at", nil], ["batch_id", nil], ["batch_callback_id", nil], ["executions_count", nil], ["job_class", "TestJob"], ["error_event", nil], ["labels", nil], ["locked_by_id", nil], ["locked_at", nil]] [🐤 RSpec: can accept a limit 🐤] [ActiveJob] TRANSACTION (0.3ms) COMMIT [🐤 RSpec: can accept a limit 🐤] [ActiveJob] SQL (0.2ms) NOTIFY good_job, '{"queue_name":"default","scheduled_at":"2024-07-18T15:43:21.414Z"}' [🐤 RSpec: can accept a limit 🐤] [ActiveJob] (0.3ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐤 RSpec: can accept a limit 🐤] [ActiveJob] Enqueued TestJob (Job ID: 826fca11-5f34-44a1-a8c0-42f582b38b7b) to (default) [🐤 RSpec: can accept a limit 🐤] [ActiveJob] TRANSACTION (0.1ms) BEGIN [🐤 RSpec: can accept a limit 🐤] [ActiveJob] GoodJob::Job Create (0.6ms) INSERT INTO "good_jobs" ("id", "queue_name", "priority", "serialized_params", "scheduled_at", "performed_at", "finished_at", "error", "created_at", "updated_at", "active_job_id", "concurrency_key", "cron_key", "cron_at", "batch_id", "batch_callback_id", "executions_count", "job_class", "error_event", "labels", "locked_by_id", "locked_at") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13, $14, $15, $16, $17, $18, $19, $20, $21, $22) RETURNING "id" [["id", "09732317-0853-46e6-87ca-de74172bb82b"], ["queue_name", "default"], ["priority", 0], ["serialized_params", "{\"job_class\":\"TestJob\",\"job_id\":\"09732317-0853-46e6-87ca-de74172bb82b\",\"provider_job_id\":null,\"queue_name\":\"default\",\"priority\":null,\"arguments\":[],\"executions\":0,\"exception_executions\":{},\"locale\":\"en\",\"timezone\":\"UTC\",\"enqueued_at\":\"2024-07-18T15:43:21.418531506Z\",\"scheduled_at\":null}"], ["scheduled_at", "2024-07-18 15:43:21.418543"], ["performed_at", nil], ["finished_at", nil], ["error", nil], ["created_at", "2024-07-18 15:43:21.418543"], ["updated_at", "2024-07-18 15:43:21.419185"], ["active_job_id", "09732317-0853-46e6-87ca-de74172bb82b"], ["concurrency_key", nil], ["cron_key", nil], ["cron_at", nil], ["batch_id", nil], ["batch_callback_id", nil], ["executions_count", nil], ["job_class", "TestJob"], ["error_event", nil], ["labels", nil], ["locked_by_id", nil], ["locked_at", nil]] [🐤 RSpec: can accept a limit 🐤] [ActiveJob] TRANSACTION (0.3ms) COMMIT [🐤 RSpec: can accept a limit 🐤] [ActiveJob] SQL (0.2ms) NOTIFY good_job, '{"queue_name":"default","scheduled_at":"2024-07-18T15:43:21.418Z"}' [🐤 RSpec: can accept a limit 🐤] [ActiveJob] (0.4ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐤 RSpec: can accept a limit 🐤] [ActiveJob] Enqueued TestJob (Job ID: 09732317-0853-46e6-87ca-de74172bb82b) to (default) [🐤 RSpec: can accept a limit 🐤] TRANSACTION (0.1ms) BEGIN [🐤 RSpec: can accept a limit 🐤] GoodJob::Process Create (0.4ms) INSERT INTO "good_job_processes" ("id", "created_at", "updated_at", "state", "lock_type") VALUES ($1, $2, $3, $4, $5) RETURNING "id" [["id", "4ffb5b1e-8cc1-4bf2-b60c-09509f3baf3b"], ["created_at", "2024-07-18 15:43:21.423016"], ["updated_at", "2024-07-18 15:43:21.423016"], ["state", "{\"hostname\":\"fv-az1148-542\",\"pid\":3849,\"proctitle\":\"/home/runner/work/good_job/good_job/gemfiles/vendor/bundle/ruby/3.2.0/bin/rspec\",\"preserve_job_records\":true,\"retry_on_unhandled_error\":false,\"schedulers\":[],\"cron_enabled\":false,\"total_succeeded_executions_count\":0,\"total_errored_executions_count\":0,\"database_connection_pool\":{\"size\":20,\"active\":0}}"], ["lock_type", nil]] [🐤 RSpec: can accept a limit 🐤] TRANSACTION (0.3ms) COMMIT [🐤 RSpec: can accept a limit 🐤] GoodJob::Job Load (1.5ms) 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" FROM "good_jobs" WHERE "good_jobs"."finished_at" IS NULL AND ("good_jobs"."scheduled_at" <= $1 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 $2) ORDER BY priority ASC NULLS LAST, "good_jobs"."created_at" ASC [["scheduled_at", "2024-07-18 15:43:21.424618"], ["LIMIT", 1]] [🐤 RSpec: can accept a limit 🐤] GoodJob::Job Load (0.2ms) 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" = $1 LIMIT $2 [["id", "826fca11-5f34-44a1-a8c0-42f582b38b7b"], ["LIMIT", 1]] [🐤 RSpec: can accept a limit 🐤] TRANSACTION (0.1ms) BEGIN [🐤 RSpec: can accept a limit 🐤] GoodJob::Execution Create (0.5ms) INSERT INTO "good_job_executions" ("created_at", "updated_at", "active_job_id", "job_class", "queue_name", "serialized_params", "scheduled_at", "finished_at", "error", "error_event", "error_backtrace", "process_id", "duration") VALUES ($1, $2, $3, $4, $5, $6, $7, $8, $9, $10, $11, $12, $13) RETURNING "id" [["created_at", "2024-07-18 15:43:21.428098"], ["updated_at", "2024-07-18 15:43:21.429045"], ["active_job_id", "826fca11-5f34-44a1-a8c0-42f582b38b7b"], ["job_class", "TestJob"], ["queue_name", "default"], ["serialized_params", "{\"job_id\":\"826fca11-5f34-44a1-a8c0-42f582b38b7b\",\"locale\":\"en\",\"priority\":null,\"timezone\":\"UTC\",\"arguments\":[],\"job_class\":\"TestJob\",\"executions\":0,\"queue_name\":\"default\",\"enqueued_at\":\"2024-07-18T15:43:21.414061913Z\",\"scheduled_at\":null,\"provider_job_id\":null,\"exception_executions\":{}}"], ["scheduled_at", "2024-07-18 15:43:21.414083"], ["finished_at", nil], ["error", nil], ["error_event", nil], ["error_backtrace", nil], ["process_id", "4ffb5b1e-8cc1-4bf2-b60c-09509f3baf3b"], ["duration", nil]] [🐤 RSpec: can accept a limit 🐤] GoodJob::Job Update (0.4ms) UPDATE "good_jobs" SET "performed_at" = $1, "updated_at" = $2, "executions_count" = $3, "locked_by_id" = $4, "locked_at" = $5 WHERE "good_jobs"."id" = $6 [["performed_at", "2024-07-18 15:43:21.428098"], ["updated_at", "2024-07-18 15:43:21.430279"], ["executions_count", 1], ["locked_by_id", "4ffb5b1e-8cc1-4bf2-b60c-09509f3baf3b"], ["locked_at", "2024-07-18 15:43:21.428428"], ["id", "826fca11-5f34-44a1-a8c0-42f582b38b7b"]] [🐤 RSpec: can accept a limit 🐤] TRANSACTION (0.4ms) COMMIT [🐤 RSpec: can accept a limit 🐤] [ActiveJob] [TestJob] [826fca11-5f34-44a1-a8c0-42f582b38b7b] Performing TestJob (Job ID: 826fca11-5f34-44a1-a8c0-42f582b38b7b) from (default) enqueued at 2024-07-18T15:43:21.414061913Z [🐤 RSpec: can accept a limit 🐤] [ActiveJob] [TestJob] [826fca11-5f34-44a1-a8c0-42f582b38b7b] Performed TestJob (Job ID: 826fca11-5f34-44a1-a8c0-42f582b38b7b) from (default) in 0.19ms [🐤 RSpec: can accept a limit 🐤] [GoodJob] [3849] [RSpec: can accept a limit] Executed GoodJob 826fca11-5f34-44a1-a8c0-42f582b38b7b [🐤 RSpec: can accept a limit 🐤] TRANSACTION (0.1ms) BEGIN [🐤 RSpec: can accept a limit 🐤] GoodJob::Execution Update (0.3ms) UPDATE "good_job_executions" SET "updated_at" = $1, "finished_at" = $2, "duration" = $3 WHERE "good_job_executions"."id" = $4 [["updated_at", "2024-07-18 15:43:21.432715"], ["finished_at", "2024-07-18 15:43:21.432263"], ["duration", "PT0.0041664489999675425S"], ["id", "5e59b131-4587-4eb2-9e66-d6295a93726e"]] [🐤 RSpec: can accept a limit 🐤] GoodJob::Job Update (0.3ms) UPDATE "good_jobs" SET "locked_by_id" = $1, "locked_at" = $2, "finished_at" = $3, "updated_at" = $4 WHERE "good_jobs"."id" = $5 [["locked_by_id", nil], ["locked_at", nil], ["finished_at", "2024-07-18 15:43:21.432263"], ["updated_at", "2024-07-18 15:43:21.433495"], ["id", "826fca11-5f34-44a1-a8c0-42f582b38b7b"]] [🐤 RSpec: can accept a limit 🐤] TRANSACTION (0.3ms) COMMIT [🐤 RSpec: can accept a limit 🐤] GoodJob::Lockable Advisory Unlock (0.2ms) SELECT pg_advisory_unlock(('x'||substr(md5($1::text), 1, 16))::bit(64)::bigint) AS unlocked [["key", "good_jobs-826fca11-5f34-44a1-a8c0-42f582b38b7b"]] [🐤 RSpec: can accept a limit 🐤] TRANSACTION (0.1ms) BEGIN [🐤 RSpec: can accept a limit 🐤] GoodJob::Process Destroy (0.2ms) DELETE FROM "good_job_processes" WHERE "good_job_processes"."id" = $1 [["id", "4ffb5b1e-8cc1-4bf2-b60c-09509f3baf3b"]] [🐤 RSpec: can accept a limit 🐤] GoodJob::Job Update All (0.2ms) UPDATE "good_jobs" SET "locked_by_id" = $1 WHERE "good_jobs"."locked_by_id" = $2 [["locked_by_id", nil], ["locked_by_id", "4ffb5b1e-8cc1-4bf2-b60c-09509f3baf3b"]] [🐤 RSpec: can accept a limit 🐤] TRANSACTION (0.3ms) COMMIT [🐤 RSpec: can accept a limit 🐤] (0.3ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐤 RSpec: can accept a limit 🐤] Connection returned to pool with 1 advisory locks [🐤 RSpec: can accept a limit 🐤] PgLock Exists? (0.5ms) SELECT 1 AS one FROM "pg_locks" JOIN pg_database ON pg_database.oid = pg_locks.database WHERE (pg_database.datname = current_database()) AND "pg_locks"."locktype" = $1 AND (pid = pg_backend_pid()) LIMIT $2 [["locktype", "advisory"], ["LIMIT", 1]] [🐤 RSpec: can accept a limit 🐤] PgLock Count (0.4ms) SELECT COUNT(*) FROM "pg_locks" JOIN pg_database ON pg_database.oid = pg_locks.database WHERE (pg_database.datname = current_database()) AND "pg_locks"."locktype" = $1 AND (pid = pg_backend_pid()) [["locktype", "advisory"]] [🐤 RSpec: can accept a limit 🐤] GoodJob::Job Load (0.8ms) 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" 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"."id"::text), 1, 16))::bit(32)::int AND pg_locks.objid = (('x' || substr(md5('good_jobs' || '-' || "good_jobs"."id"::text), 1, 16))::bit(64) << 32)::bit(32)::int WHERE "pg_locks"."locktype" IS NOT NULL AND ("pg_locks"."pid" = pg_backend_pid()) [🐤 RSpec: can accept a limit 🐤] PgLock Load (0.4ms) SELECT "pg_locks".* FROM "pg_locks" JOIN pg_database ON pg_database.oid = pg_locks.database WHERE (pg_database.datname = current_database()) AND "pg_locks"."locktype" = $1 AND (pid = pg_backend_pid()) [["locktype", "advisory"]] [🐤 RSpec: can accept a limit 🐤] PgStatActivity Load (0.5ms) SELECT "pg_stat_activity".* FROM "pg_stat_activity" WHERE "pg_stat_activity"."pid" = $1 [["pid", 1027]] [🐤 RSpec: can accept a limit 🐤] PgStatActivity Load (0.8ms) SELECT "pg_stat_activity".* FROM "pg_stat_activity" [🐤 RSpec: can accept a limit 🐤] CACHE PgLock Count (0.0ms) SELECT COUNT(*) FROM "pg_locks" JOIN pg_database ON pg_database.oid = pg_locks.database WHERE (pg_database.datname = current_database()) AND "pg_locks"."locktype" = $1 AND (pid = pg_backend_pid()) [["locktype", "advisory"]] [🐤 RSpec: can accept a limit 🐤] (0.4ms) SELECT count(*) FROM pg_locks WHERE database = (SELECT oid FROM pg_database WHERE datname = current_database()) AND pid = pg_backend_pid() AND locktype = 'advisory' [🐤 RSpec: can accept a limit 🐤] Connection returned to pool with 1 advisory locks [🐤 RSpec: can accept a limit 🐤] ```