recurring_tasks - ActiveRecord::NotNullViolation SQLite3::ConstraintException - wait, what?

[wdiechmann]

hi Rosa,

I'm painfully aware that you cannot run this 'private support hotline for Walther' but I'm confused by

20:18:00 web.1  | [ActiveJob] Enqueued BackgroundManagerJob (Job ID: 93b0b28d-db0c-4b92-b721-5dedfe2e82e3) to SolidQueue(default)
20:18:00 web.1  | [writer]   TRANSACTION (0.1ms)  begin transaction
20:18:00 web.1  | [writer]   SolidQueue::RecurringExecution Insert (0.7ms)  INSERT INTO "solid_queue_recurring_executions" ("job_id","task_key","run_at","created_at") VALUES (NULL, 'background_job_scheduler', '2024-08-20 18:18:00', STRFTIME('%Y-%m-%d %H:%M:%f', 'NOW')) ON CONFLICT ("task_key","run_at") DO NOTHING RETURNING "id"
20:18:00 web.1  | [writer]   TRANSACTION (0.1ms)  rollback transaction
20:18:00 web.1  | SolidQueue-0.5.0 Error enqueuing recurring task (46.4ms)  task: "background_job_scheduler", at: "2024-08-20T18:18:00Z"
20:18:00 web.1  | SolidQueue-0.5.0 Error in thread (0.0ms)  error: "ActiveRecord::NotNullViolation SQLite3::ConstraintException: NOT NULL constraint failed: solid_queue_recurring_executions.job_id"

yet doing

mortimer(dev)> BackgroundManagerJob.perform_now
Performing BackgroundManagerJob (Job ID: 62bd5659-8d36-4ba0-853a-e464662e77fe) from SolidQueue(default)
↳ (mortimer):3:in `<main>'
Performing BackgroundManagerJob
Performed BackgroundManagerJob (Job ID: 62bd5659-8d36-4ba0-853a-e464662e77fe) from SolidQueue(default) in 1.42ms
↳ (mortimer):3:in `<main>'
=> true

and further - when I look at the SQLite table it does looks right (AFAICS)

mortimer(dev)> SolidQueue::RecurringTask.first
  SolidQueue::RecurringTask Load (0.1ms)  SELECT "solid_queue_recurring_tasks".* FROM "solid_queue_recurring_tasks" ORDER BY "solid_queue_recurring_tasks"."id" ASC LIMIT ?  [["LIMIT", 1]]
=> 
#<SolidQueue::RecurringTask:0x0000000108914f98
 id: 1,
 key: "background_job_scheduler",
 schedule: "every minute",
 command: nil,
 class_name: "BackgroundManagerJob",
 arguments: [],
 queue_name: nil,
 priority: 0,
 static: true,
 description: nil,
 created_at: "2024-08-20 18:01:46.732000000 +0000",
 updated_at: "2024-08-20 18:01:46.732000000 +0000">
mortimer(dev)> 

[wdiechmann]

adding spice to the stew here is the result of doing BackgroundManagerJob.perform_later

mortimer(dev)> BackgroundManagerJob.perform_later
  TRANSACTION (0.0ms)  begin transaction
  SolidQueue::Job Create (2.8ms)  INSERT INTO "solid_queue_jobs" ("queue_name", "class_name", "arguments", "priority", "active_job_id", "scheduled_at", "finished_at", "concurrency_key", "created_at", "updated_at") VALUES (?, ?, ?, ?, ?, ?, ?, ?, ?, ?) RETURNING "id"  [["queue_name", "default"], ["class_name", "BackgroundManagerJob"], ["arguments", "{\"job_class\":\"BackgroundManagerJob\",\"job_id\":\"fb2c6111-43e3-4804-a079-2f31658e5949\",\"provider_job_id\":null,\"queue_name\":\"default\",\"priority\":null,\"arguments\":[],\"executions\":0,\"exception_executions\":{},\"locale\":\"da\",\"timezone\":\"UTC\",\"enqueued_at\":\"2024-08-21T05:47:39.105775000Z\",\"scheduled_at\":\"2024-08-21T05:47:39.105700000Z\"}"], ["priority", 0], ["active_job_id", "fb2c6111-43e3-4804-a079-2f31658e5949"], ["scheduled_at", "2024-08-21 05:47:39.105700"], ["finished_at", nil], ["concurrency_key", "[FILTERED]"], ["created_at", "2024-08-21 05:47:39.110654"], ["updated_at", "2024-08-21 05:47:39.110654"]]
  TRANSACTION (0.0ms)  SAVEPOINT active_record_1
  SolidQueue::Job Load (0.2ms)  SELECT "solid_queue_jobs".* FROM "solid_queue_jobs" WHERE "solid_queue_jobs"."id" = ? LIMIT ?  [["id", 1490], ["LIMIT", 1]]
  SolidQueue::ReadyExecution Create (0.1ms)  INSERT INTO "solid_queue_ready_executions" ("job_id", "queue_name", "priority", "created_at") VALUES (?, ?, ?, ?) RETURNING "id"  [["job_id", 1490], ["queue_name", "default"], ["priority", 0], ["created_at", "2024-08-21 05:47:39.122626"]]
  TRANSACTION (0.0ms)  RELEASE SAVEPOINT active_record_1
  TRANSACTION (0.1ms)  commit transaction
Enqueued BackgroundManagerJob (Job ID: fb2c6111-43e3-4804-a079-2f31658e5949) to SolidQueue(default)

which is fine - and now begs the question: why can solid_queue.yml

default: &default
  dispatchers:
    - polling_interval: 1
      batch_size: 500
      recurring_tasks:
        background_job_scheduler:
          interval: 60
          class: BackgroundManagerJob
          queue: default
          schedule: every minute
          enabled: true
  workers:
    - queues: "*"
      threads: 5
      processes: 1
      polling_interval: 0.1

development:
 <<: *default

test:
 <<: *default

production:
 <<: *default

not perform when set into manual gear all seems good and well?

[rosa]

Oh, no worries at all! This is strange! Do you happen to have this setting in your app:

config.active_job.enqueue_after_transaction_commit = :always

[wdiechmann]

oh yes - read somewhere that I had to!? 😟

[rosa]

Ahh, great! Then you're hitting a real bug that I had to fix 😅 I'll get to this one very soon. In the meantime, you can work around the bug by setting:

  self.enqueue_after_transaction_commit = :never

in your BackgroundManagerJob class.

So sorry about that! I'll get a fix soon so you can remove that.

[wdiechmann]

and my database.yml looks like this (using two connections in dev b'c i'm testing out some performance

default: &default
  adapter: sqlite3
  pool: <%= ENV.fetch("RAILS_MAX_THREADS") { 5 } %>
  timeout: 5000
development:
  writer:
    <<: *default
    pool: 1
    database: storage/development.sqlite3
  reader:
    <<: *default
    readonly: true
    database: storage/development.sqlite3
test:
  <<: *default
  database: storage/test.sqlite3
production:
  <<: *default
  database: storage/mortimer-bellis.sqlite3

[wdiechmann]

wonderful - i'm very impressed with your report @rosa !!!

[rosa]

Getting a fix ready for this, sorry about that! https://github.com/rails/solid_queue/pull/290