Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

SQLite queue database corruption #324

Closed
andycroll opened this issue Sep 5, 2024 · 85 comments
Closed

SQLite queue database corruption #324

andycroll opened this issue Sep 5, 2024 · 85 comments

Comments

@andycroll
Copy link

I'm seeing a strange error. I dropped @fractaledmind a note and he suggested I post here.

W, [2024-09-05T18:49:32.074281 #809854]  WARN -- : SolidQueue-0.3.4 Error deregistering Supervisor (1.1ms)  process_id: 68, pid: 564289, hostname: "HOST", last_heartbeat_at: Sat, 31 Aug 2024 15:16:55.474066000 UTC +00:00, claimed_size: 0, pruned: {:process=>#<SolidQueue::Process id: 68>, :pruned=>true, :claimed_size=>0, :error=>#<ActiveRecord::StatementInvalid: SQLite3::CorruptException: database disk image is malformed>, :exception=>["ActiveRecord::StatementInvalid", "SQLite3::CorruptException: database disk image is malformed"], :exception_object=>#<ActiveRecord::StatementInvalid: SQLite3::CorruptException: database disk image is malformed>}, error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"

In sqlite3 client.

sqlite> .open production-queue.sqlite3
sqlite> pragma integrity_check;
*** in database main ***
On tree page 523 cell 23: Rowid 146 out of order
NULL value in solid_queue_jobs.created_at
NULL value in solid_queue_jobs.updated_at
row 146 missing from index index_solid_queue_jobs_for_alerting
row 146 missing from index index_solid_queue_jobs_for_filtering
row 146 missing from index index_solid_queue_jobs_on_finished_at
row 146 missing from index index_solid_queue_jobs_on_active_job_id
row 146 missing from index index_solid_queue_jobs_on_class_name
NULL value in solid_queue_jobs.created_at
NULL value in solid_queue_jobs.updated_at
row 147 missing from index index_solid_queue_jobs_for_alerting
row 147 missing from index index_solid_queue_jobs_for_filtering
row 147 missing from index index_solid_queue_jobs_on_finished_at
row 147 missing from index index_solid_queue_jobs_on_active_job_id
row 147 missing from index index_solid_queue_jobs_on_class_name
NULL value in solid_queue_jobs.created_at
NULL value in solid_queue_jobs.updated_at
row 148 missing from index index_solid_queue_jobs_for_alerting
row 148 missing from index index_solid_queue_jobs_for_filtering
row 148 missing from index index_solid_queue_jobs_on_finished_at
row 148 missing from index index_solid_queue_jobs_on_active_job_id
row 148 missing from index index_solid_queue_jobs_on_class_name
NULL value in solid_queue_jobs.created_at
NULL value in solid_queue_jobs.updated_at
row 149 missing from index index_solid_queue_jobs_for_alerting
row 149 missing from index index_solid_queue_jobs_for_filtering
row 149 missing from index index_solid_queue_jobs_on_finished_at
row 149 missing from index index_solid_queue_jobs_on_active_job_id
row 149 missing from index index_solid_queue_jobs_on_class_name
Error: stepping, database disk image is malformed (11)
sqlite> pragma integrity_check;
*** in database main ***
On tree page 523 cell 23: Rowid 146 out of order
NULL value in solid_queue_jobs.created_at
NULL value in solid_queue_jobs.updated_at
row 146 missing from index index_solid_queue_jobs_for_alerting
row 146 missing from index index_solid_queue_jobs_for_filtering
row 146 missing from index index_solid_queue_jobs_on_finished_at
row 146 missing from index index_solid_queue_jobs_on_active_job_id
row 146 missing from index index_solid_queue_jobs_on_class_name
Error: stepping, database disk image is malformed (11)

Doing a .clone doesn't seem to fix.

I'm not in "real" production and this is a job queue and thus somewhat destroyable, so I'm going to take that approach.

I've also seen similar corruption on my local development environment too akin to that mentioned by @marcoroth on X.

https://x.com/marcoroth_/status/1831045885423497223

In that case I just destroyed and recreated the file and moved on.

@marcoroth
Copy link

Yes, this is excactly what I was seeing as well. Thanks for opening the issue and tagging me @andycroll as I wanted to open an issue for this too 🙌🏼

This happened to me in this open source repo: http://github.com/adrienpoly/rubyvideo

You can easily reproduce it by running rails s as a separate process and doing a double Ctrl-C in quick succession.

I think it only happens with the Puma Plugin from what I could tell.

@andycroll
Copy link
Author

In production, I'm running as a separate worker, not the puma plugin.

@rosa
Copy link
Member

rosa commented Sep 5, 2024

Ohhh! See also #294, where @wdiechmann provided some advice in the last comment, which I'm not sure if it applies to your case.

The Puma plugin detail is quite interesting! Did you manage to reproduce only with that?

@rosa
Copy link
Member

rosa commented Sep 5, 2024

Ah, sorry, just reread and I see @andycroll's error happened when running just the supervisor separately 🤔
Do you know what happened right before that?

@andycroll
Copy link
Author

In my case a deploy (on a Hatchbox managed server) so killing the worker process was certainly happening when the error started.

@rosa
Copy link
Member

rosa commented Sep 5, 2024

It's also very surprising to me that you can corrupt a database with only Active Record and quite regular queries 🤔

*** in database main ***
On tree page 523 cell 23: Rowid 146 out of order
NULL value in solid_queue_jobs.created_at
NULL value in solid_queue_jobs.updated_at
row 146 missing from index index_solid_queue_jobs_for_alerting
row 146 missing from index index_solid_queue_jobs_for_filtering
row 146 missing from index index_solid_queue_jobs_on_finished_at
row 146 missing from index index_solid_queue_jobs_on_active_job_id
row 146 missing from index index_solid_queue_jobs_on_class_name
NULL value in solid_queue_jobs.created_at
NULL value in solid_queue_jobs.updated_at

I wouldn't know how to cause this on purpose 😅 A row missing from an index? 🤔

I'll use @marcoroth's instructions to reproduce and see if I can find out what's going on!

@fractaledmind
Copy link

I haven't been able to dig in myself yet, but after reading this: https://www.sqlite.org/howtocorrupt.html and knowing the bits that I know about the supervisor architecture, I was first drawn to:

2.6. Carrying an open database connection across a fork()

@marcoroth
Copy link

If it helps, here's how my pragma integrity_check looks like:

❯ sqlite3
SQLite version 3.43.2 2023-10-10 13:08:14
Enter ".help" for usage hints.
Connected to a transient in-memory database.
Use ".open FILENAME" to reopen on a persistent database.
sqlite> .open ./storage/development-queue.sqlite3
sqlite> pragma integrity_check;
row 1 missing from index index_solid_queue_processes_on_supervisor_id
row 2 missing from index index_solid_queue_processes_on_supervisor_id
row 3 missing from index index_solid_queue_processes_on_supervisor_id
wrong # of entries in index index_solid_queue_processes_on_supervisor_id
sqlite>

@rosa
Copy link
Member

rosa commented Sep 5, 2024

Ohhhh, thanks a lot @fractaledmind. That'd make perfect sense as the culprit! I thought Rails would handle this properly and wouldn't reuse the same connection but I need to dig more.

@fractaledmind
Copy link

Yeah, this sounds like it might be what is occurring:

Do not even call sqlite3_close() on a database connection from a child process if the connection was opened in the parent. It is safe to close the underlying file descriptor, but the sqlite3_close() interface might invoke cleanup activities that will delete content out from under the parent, leading to errors and perhaps even database corruption.

@rosa
Copy link
Member

rosa commented Sep 6, 2024

I thought Rails would handle this properly and wouldn't reuse the same connection but I need to dig more.

The reason I thought that were these PRs that I had looked at in the past, because of another error (not as serious as this one) that someone reported with PostgreSQL 🤔

There must be something else going on here.

@fractaledmind
Copy link

No idea yet if this is related, but rails/rails#31173 has this in the description:

I think sqlite3 is immune to this problem just because there is no server to confuse.

And no discard! method is defined (in that PR or currently) for the SQLite3 AR adapter

@rosa
Copy link
Member

rosa commented Sep 6, 2024

Thanks @fractaledmind! I see this code has changed quite a lot since these PRs, (for example rails/rails#37296), so I was trying to understand how everything worked... That comment caught my attention too but I honestly wasn't sure why "there is no server to confuse" makes SQLite immune to this problem 😳

@marcoroth, I've been trying to reproduce the problem following your steps but I can't. I have to say I have upgraded Solid Queue in rubyvideo to version 0.8.2 as it was using a quite old version so maybe there's something else at play there.

@rosa
Copy link
Member

rosa commented Sep 6, 2024

I have to say I have upgraded Solid Queue in rubyvideo to version 0.8.2 as it was using a quite old version so maybe there's something else at play there.

Tried without upgrading and same thing... I can't manage to reproduce it by starting the app with rails s and then Ctrl + C, double, in quick succession 😕

@rosa
Copy link
Member

rosa commented Sep 6, 2024

I've also tried to artificially delay the jobs that are being run (in particular, MeiliSearch::Rails::MSJob, that were failing because I don't have Meilisearch running, so they were failing very fast) by adding some sleeps there, and still same behaviour. I don't manage to corrupt the file.

@rosa
Copy link
Member

rosa commented Sep 6, 2024

Oh, @andycroll, I just realised you're running version 0.3.4 in your logs above. The issue I referred to previously with PostgreSQL (#264) got fixed in version 0.4.0. However, in the rubyvideo repo, solid_queue has been on version >= 0.4.0 for a few weeks. @marcoroth, can you reliably reproduce it with that version still? Just to make sure.

@fractaledmind
Copy link

@marcoroth: I created this repo to hopefully help us find a reproduction: https://github.com/fractaledmind/solid_queue_bughunt

You will see that I have a LongRunningQueryJob that I enqueue automatically once Solid Queue is loaded. I am trying to ctrl + c twice once the job starts up such that the Rails process is killed and the job dies. But, the job always resolves. I'm curious what your experience is. Can you get everything to stop mid-operation? Or does the job eventually resolve for you to?

You can see if the job eventually resolves by just waiting 5 seconds or so after you kill the Rails process and waiting for logs to print. All you have to do is bin/rails s and everything goes automatically.

You will see I have commented out automatically killing the Rails server process. I was trying that as well. Still, the job resolves. My hunch is that it is/was somehow possible to force Solid Queue to not stop gracefully and if a job was running and connected to the database, that could corrupt. But I am not sure. Maybe if we all work on this reproduction repo, we can hunt it down.

@rosa
Copy link
Member

rosa commented Sep 6, 2024

Thanks a lot @fractaledmind! 🙏 I've been playing with it a bit, also tried downgrading Solid Queue there to 0.3.4 just in case. I've tried deleting the USR1 signal and just killing the Solid Queue supervisor in different ways, even via SIGKILL. So far I've only managed to get these

SolidQueue-0.3.4 Error deregistering Worker (21.1ms)  process_id: 15, pid: 96758, hostname: "Rosas-Air-M2.localdomain", last_heartbeat_at: Fri, 06 Sep 2024 14:46:55.769528000 UTC +00:00, claimed_size: 2, pruned: {:process=>#<SolidQueue::Process id: 15, kind: "Worker", last_heartbeat_at: "2024-09-06 14:46:55.769528000 +0000", supervisor_id: 13, pid: 96758, hostname: "Rosas-Air-M2.localdomain", metadata: {"polling_interval"=>0.1, "queues"=>"*", "thread_pool_size"=>3}, created_at: "2024-09-06 14:46:55.778267000 +0000">, :pruned=>false, :claimed_size=>3, :error=>#<ActiveRecord::StatementInvalid: SQLite3::BusyException: database is locked>, :exception=>["ActiveRecord::StatementInvalid", "SQLite3::BusyException: database is locked"], :exception_object=>#<ActiveRecord::StatementInvalid: SQLite3::BusyException: database is locked>}, error: "ActiveRecord::StatementInvalid SQLite3::BusyException: database is locked"
SolidQueue-0.3.4 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::BusyException: database is locked"
SolidQueue-0.3.4 Shut down Worker (32876.4ms)  pid: 96758, hostname: "Rosas-Air-M2.localdomain", polling_interval: 0.1, queues: "*", thread_pool_size: 3

but I think those were expected as I tried to start the server again when the workers themselves hadn't realised their parent had been killed and were still around.

@fractaledmind
Copy link

Also, here is a one-liner to check the queue database integrity: sqlite3 storage/development-queue.sqlite3 'pragma integrity_check;'

@rosa
Copy link
Member

rosa commented Sep 6, 2024

Nothing so far. Tried also configuring recurring long running jobs (that don't send any signals) every 10 seconds to add more stuff to the mix (and because that other report of a corrupted file was using recurring jobs heavily), but still haven't managed to reproduce this 😖

@rosa
Copy link
Member

rosa commented Sep 6, 2024

I'm trying to hang to any possible thread here as I'm quite stumped about why I can't manage to reproduce this 😅

In my case a deploy (on a Hatchbox managed server) so killing the worker process was certainly happening when the error started.

@andycroll, do you know how the deploy is happening there? Does it happen by sending a specific signal to the Solid Queue process so it stops? With any grace period to terminate orderly? Or just terminate and then "pull the plug" right away...?

@marcoroth
Copy link

Is there any chance that this is dependent on the sqlite3 gem variant you get?

I'm running the x86_64-darwin one (and I assume @andycroll is probably also running a x86_64-* variant in production) whereas most of you are probably running a arm64-* variant on your local dev machines.

@npezza93
Copy link

npezza93 commented Sep 6, 2024

I have had this happen twice on my local dev machine this week while running in the puma plugin and im on arm64. Unfortunately have no clue how it happened. I thought it might have something to do with switching between the puma plugin and running bin/jobs start and killing the process mid job but i cant recreate again. /shrug

@npezza93
Copy link

npezza93 commented Sep 6, 2024

Im also using a separate db for queue stuff if that matters at all.

@fractaledmind
Copy link

@npezza93: Try pulling down my repro repo and see if you can set something up that causes corruption consistently: https://github.com/fractaledmind/solid_queue_bughunt

Until we find a way to reproduce, we will never solve this.

@marcoroth
Copy link

I upgraded SolidQueue to 0.6.0 so I could later upgrade to 0.8.x to see if the issue is still present on the latest version.

But I couldn't reproduce it on 0.6.0. And now, after downgrading again, I can't reproduce it on 0.5.0 anymore weirdly enough 🤔

Prior to upgrading to 0.6.0 I was able to reliably reproduce it.

@npezza93
Copy link

npezza93 commented Sep 6, 2024

I think im on to something. Just had it happen to me. Cant quite reproduce reliably yet but i think it may have something to do with me keeping the server running with the puma plugin running and closing my laptop for some period of time. Cant confirm yet but just a hunch. Will report back if i mind reliable instructions. Heres the log. It's weird that there are rollbacks happening trying to update the Process model and then it corrupts.

Turbo::StreamsChannel is transmitting the subscription confirmation
Turbo::StreamsChannel is streaming from Z2lkOi8vcWlyYS9TZWN1cml0eS80Nw:chart:1D
Unsubscribing from channel: {"channel":"Turbo::StreamsChannel","signed_stream_name":"IloybGtPaTh2Y1dseVlTOVRaV04xY21sMGVTODBOdzpjaGFydDoxRCI=--6b7a8177c089474a55c40174ae74943ecba61bc5effaf1d922cc00e95ded31a4"}
Turbo::StreamsChannel stopped streaming from Z2lkOi8vcWlyYS9TZWN1cml0eS80Nw:chart:1D
Turbo::StreamsChannel is transmitting the subscription confirmation
Turbo::StreamsChannel is streaming from Z2lkOi8vcWlyYS9TZWN1cml0eS80Nw:chart:1D
  �[1m�[35mSQL (0.2ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (3.9ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:20:18.968432"], ["id", 93]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.1ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:20:19.144763"], ["id", 95]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.6ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:20:19.164246"], ["id", 96]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.7ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:20:19.169932"], ["id", 98]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (8.7ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (9.5ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:20:19.164249"], ["id", 97]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (13.8ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (15.1ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:20:19.164685"], ["id", 94]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.7ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:20:19.196651"], ["id", 99]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.5ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:21:19.012875"], ["id", 93]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.7ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:21:19.160688"], ["id", 95]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.6ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:21:19.176302"], ["id", 96]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.1ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:21:19.177137"], ["id", 98]]
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.8ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:21:19.184487"], ["id", 94]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (3.6ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (4.3ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:21:19.184518"], ["id", 97]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.0ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:21:19.201697"], ["id", 99]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Load (0.1ms)�[0m  �[1m�[34mSELECT "solid_queue_processes".* FROM "solid_queue_processes" WHERE "solid_queue_processes"."last_heartbeat_at" <= ? ORDER BY "solid_queue_processes"."id" ASC LIMIT ? �[0m  [["last_heartbeat_at", "2024-09-06 14:17:18.947007"], ["LIMIT", 50]]
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Destroy (1.1ms)�[0m  �[1m�[31mDELETE FROM "solid_queue_processes" WHERE "solid_queue_processes"."id" = ?�[0m  [["id", 8]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error deregistering Supervisor (4.8ms)  process_id: 8, pid: 87668, hostname: "Nicks-MacBook-Air.local", name: "supervisor-fb2dc5791db13f37a778", last_heartbeat_at: "2024-09-05T23:20:38-04:00", claimed_size: nil, pruned: true, error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
SolidQueue-0.8.2 Prune dead processes (30.5ms)  size: 13
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (2.0ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:22:19.021586"], ["id", 93]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.4ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:22:19.165340"], ["id", 95]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.5ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:22:19.181037"], ["id", 96]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.9ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:22:19.182902"], ["id", 98]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.5ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:22:19.192213"], ["id", 94]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.4ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:22:19.194242"], ["id", 97]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.1ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:22:19.210680"], ["id", 99]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.2ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:23:19.027648"], ["id", 93]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.3ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:23:19.173473"], ["id", 95]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.4ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:23:19.184874"], ["id", 96]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.5ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:23:19.187570"], ["id", 98]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.4ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:23:19.199510"], ["id", 94]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.4ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:23:19.202226"], ["id", 97]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.4ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:23:19.214210"], ["id", 99]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.2ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:24:19.033318"], ["id", 93]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (2.1ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:24:19.181729"], ["id", 95]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[36mSolidQueue::Process Update (1.8ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:24:19.187835"], ["id", 96]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[36mSolidQueue::Process Update (0.7ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:24:19.194634"], ["id", 98]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.9ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:24:19.205474"], ["id", 94]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (1.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (2.5ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:24:19.206692"], ["id", 97]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.0ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:24:19.219473"], ["id", 99]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.2ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (3.2ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:25:19.053217"], ["id", 93]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (3.1ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:25:19.195502"], ["id", 95]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (1.3ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (2.4ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:25:19.212315"], ["id", 94]]
  �[1m�[36mTRANSACTION (0.2ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (2.6ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (15.1ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:25:19.201020"], ["id", 98]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (16.3ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[36mSolidQueue::Process Update (17.1ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:25:19.201014"], ["id", 96]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (7.6ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (13.9ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:25:19.218068"], ["id", 97]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (3.9ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[36mSolidQueue::Process Update (10.3ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:25:19.228835"], ["id", 99]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.6ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:26:19.065500"], ["id", 93]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.5ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:26:19.217067"], ["id", 95]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.4ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:26:19.218612"], ["id", 94]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.1ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:26:19.223827"], ["id", 98]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.6ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:26:19.226618"], ["id", 96]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.4ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:26:19.234613"], ["id", 97]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.5ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:26:19.242735"], ["id", 99]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Load (0.3ms)�[0m  �[1m�[34mSELECT "solid_queue_processes".* FROM "solid_queue_processes" WHERE "solid_queue_processes"."last_heartbeat_at" <= ? ORDER BY "solid_queue_processes"."id" ASC LIMIT ? �[0m  [["last_heartbeat_at", "2024-09-06 14:22:18.983585"], ["LIMIT", 50]]
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Destroy (1.5ms)�[0m  �[1m�[31mDELETE FROM "solid_queue_processes" WHERE "solid_queue_processes"."id" = ?�[0m  [["id", 8]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error deregistering Supervisor (5.5ms)  process_id: 8, pid: 87668, hostname: "Nicks-MacBook-Air.local", name: "supervisor-fb2dc5791db13f37a778", last_heartbeat_at: "2024-09-05T23:20:38-04:00", claimed_size: nil, pruned: true, error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
SolidQueue-0.8.2 Prune dead processes (13.7ms)  size: 13
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.8ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:27:19.069270"], ["id", 93]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[36mSolidQueue::Semaphore Pluck (0.2ms)�[0m  �[1m�[34mSELECT "solid_queue_semaphores"."id" FROM "solid_queue_semaphores" WHERE "solid_queue_semaphores"."expires_at" < ? ORDER BY "solid_queue_semaphores"."id" ASC LIMIT ?�[0m  [["expires_at", "2024-09-06 14:27:19.140496"], ["LIMIT", 500]]
  �[1m�[36mSolidQueue::BlockedExecution Pluck (0.2ms)�[0m  �[1m�[34mSELECT DISTINCT "solid_queue_blocked_executions"."concurrency_key" FROM "solid_queue_blocked_executions" WHERE "solid_queue_blocked_executions"."expires_at" < ? LIMIT ?�[0m  [["expires_at", "2024-09-06 14:27:19.143734"], ["LIMIT", 500]]
SolidQueue-0.8.2 Unblock jobs (1.9ms)  limit: 500, size: 0
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.5ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:27:19.221337"], ["id", 95]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (2.7ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (3.7ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:27:19.224777"], ["id", 94]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (1.4ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (2.8ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:27:19.229198"], ["id", 98]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.2ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.3ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:27:19.233770"], ["id", 96]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.0ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:27:19.241697"], ["id", 97]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.2ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:27:19.250172"], ["id", 99]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (1.3ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (3.2ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:28:19.080873"], ["id", 93]]
  �[1m�[36mTRANSACTION (0.2ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.7ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:28:19.234057"], ["id", 94]]
  �[1m�[35mSQL (2.9ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (4.7ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:28:19.234057"], ["id", 95]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[36mSolidQueue::Process Update (1.0ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:28:19.240062"], ["id", 98]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (1.3ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[36mSolidQueue::Process Update (2.7ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:28:19.240870"], ["id", 96]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.9ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:28:19.246019"], ["id", 97]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.1ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:28:19.257539"], ["id", 99]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (1.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (2.9ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:29:19.091749"], ["id", 93]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.4ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:29:19.245256"], ["id", 94]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (2.7ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (3.8ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:29:19.245256"], ["id", 98]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (4.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (5.3ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:29:19.250051"], ["id", 97]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (12.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (12.9ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:29:19.247287"], ["id", 95]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (9.4ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (10.4ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:29:19.252059"], ["id", 96]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.8ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:29:19.265814"], ["id", 99]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.2ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (2.3ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:30:19.101218"], ["id", 93]]
  �[1m�[36mTRANSACTION (0.2ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.3ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:30:19.255702"], ["id", 94]]
  �[1m�[36mTRANSACTION (0.2ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.3ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (2.6ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:30:19.257937"], ["id", 98]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.2ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (2.3ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:30:19.267211"], ["id", 97]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (2.7ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (4.0ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:30:19.268574"], ["id", 96]]
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (3.4ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (4.2ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:30:19.270769"], ["id", 95]]
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (2.7ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[36mSolidQueue::Process Update (3.9ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:30:19.273699"], ["id", 99]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
SolidQueue-0.8.2 Error in thread (0.0ms)  error: "ActiveRecord::StatementInvalid SQLite3::CorruptException: database disk image is malformed"
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.8ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:31:19.112942"], ["id", 93]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.5ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:31:19.264649"], ["id", 94]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[36mCOMMIT TRANSACTION�[0m
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.3ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:31:19.272308"], ["id", 98]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (1.8ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:31:19.278502"], ["id", 97]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.4ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:31:19.287002"], ["id", 96]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (3.5ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (4.3ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:31:19.281150"], ["id", 95]]
  �[1m�[36mTRANSACTION (0.1ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[35mSQL (0.0ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Update (0.4ms)�[0m  �[1m�[33mUPDATE "solid_queue_processes" SET "last_heartbeat_at" = ? WHERE "solid_queue_processes"."id" = ?�[0m  [["last_heartbeat_at", "2024-09-06 14:31:19.287669"], ["id", 99]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Load (0.2ms)�[0m  �[1m�[34mSELECT "solid_queue_processes".* FROM "solid_queue_processes" WHERE "solid_queue_processes"."last_heartbeat_at" <= ? ORDER BY "solid_queue_processes"."id" ASC LIMIT ? �[0m  [["last_heartbeat_at", "2024-09-06 14:27:19.003458"], ["LIMIT", 50]]
  �[1m�[35mSQL (0.1ms)�[0m  �[1m�[36mBEGIN immediate TRANSACTION�[0m
  �[1m�[36mSolidQueue::Process Destroy (1.3ms)�[0m  �[1m�[31mDELETE FROM "solid_queue_processes" WHERE "solid_queue_processes"."id" = ?�[0m  [["id", 8]]
  �[1m�[36mTRANSACTION (0.0ms)�[0m  �[1m�[31mROLLBACK TRANSACTION�[0m

@fractaledmind
Copy link

That reminds me that was my hunch when I saw this a while back. I upgrade aggressively and I've been conference prepping, so I haven't seen this personally in a while. But I recall wondering if it was related to closing the laptop.

@rosa
Copy link
Member

rosa commented Sep 6, 2024

@npezza93 thanks a lot for that 🙏 It's telling that the error happens when updating the heartbeat, because the thread that runs the heartbeat task is started on the supervisor before forking 🤔

@npezza93
Copy link

npezza93 commented Sep 6, 2024

@rosa interesting!
Dumb question: What would cause the touch to rollback quietly like its doing? There are no explicit rollbacks and if it was a database thing i would expect to see something raise like it is later on. Also not seeing any after_* hooks to that may trigger the rollback 🤔

@rosa
Copy link
Member

rosa commented Sep 13, 2024

This is epic; thanks a lot @flavorjones 🙇‍♀️ 🏆

I think the conditions you describe could very well explain the very first issue from @andycroll. From your two conditions:

the parent has an open sqlite connection when it forks,
and the parent exits before the children have finished their work

The first is always true for Solid Queue. The second shouldn't be, generally, as the supervisor waits for its supervised processes before exiting, but depending on how the deployment worked (e.g. grace period and then SIGKILL?), it might have been terminated before the children exited, if it was terminated externally.

However, it wouldn't explain the other issues in macOS (like @marcoroth's example, no the examples where the computer goes to sleep; those are separate for sure), as I haven't been able to get a corrupted DB with your script after over one hour 😅 @marcoroth mentioned:

Is there any chance that this is dependent on the sqlite3 gem variant you get?

I'm running the x86_64-darwin one (and I assume @andycroll is probably also running a x86_64-* variant in production) whereas most of you are probably running a arm64-* variant on your local dev machines.

Maybe it has to do with that... I might try to reproduce with your script and x86_64-darwin on Mac.

@flavorjones

This comment was marked as outdated.

@flavorjones
Copy link
Member

Repository with a full Rails app reproduction here: https://github.com/flavorjones/2024-09-13-sqlite-corruption

@rosa
Copy link
Member

rosa commented Sep 13, 2024

Ok, I finally could reproduce this with @flavorjones's test on macOS. Yesterday when I was testing that I didn't realise I was running this version of SQLite3

1.7.2: arm64-darwin

Today, I've got the corruption error with both:

2.0.4: arm64-darwin
2.0.4: x86_64-darwin

I'm doing other tests now with different versions, there's also a difference if I reduce the number of children to 3 like yesterday.

Update: yes, the number of children makes a difference. With N=10, I get the corruption with older versions of the sqlite3 gem (tested with 1.5.0).

@flavorjones
Copy link
Member

flavorjones commented Sep 13, 2024

Git bisecting, this is the PR/commit where this behavior changed:

sparklemotion/sqlite3-ruby#392 /
sparklemotion/sqlite3-ruby@0c24631

which has to do with the lifecycle of database connections and prepared statements. Getting closer.

@flavorjones
Copy link
Member

OK, I understand what's happening. Problems result when an inherited (from the parent process) database connection is sqlite3_close()ed or a prepared statement is sqlite3_finalize()ed in the child process.

In a Rails app it seems much more likely to be a statement being finalized because of the cached statements, but it can happen with the database objects as well.

I think we should be able to work around this now that I understand the mechanism.

@fractaledmind
Copy link

OMG! You two are such absolute legends! @flavorjones you are a complete baller. @rosa you are a total magician. I am so grateful to get to work in the general vicinity of you both. I will buy you both some kind of drink in Toronto to show my thanks.

@flavorjones
Copy link
Member

OK, I hacked on the sqlite3 adapter so that it closes database connections before forking, and that seems to prevent the data corruption and disk i/o errors. I think we just need to polish the patch and land it in Rails and everything will be OK! Stay tuned.

@rosa
Copy link
Member

rosa commented Sep 14, 2024

Aww @fractaledmind you're too kind! This was all @flavorjones, he's the magician 🪄. Plus it's me who's beyond grateful to you and everyone here for the help, it's a privilege to have people like you in the community 🙇🏻‍♀️ I'm definitely the one getting you drinks at Rails World! 😆 and Marco, Nick, Andy... 🥹🙏🏻

@dhh
Copy link
Member

dhh commented Sep 14, 2024

Epic team work, all 🤘. Sqlite is going to be a much bigger role in Rails apps going forward.

flavorjones added a commit to flavorjones/rails that referenced this issue Sep 14, 2024
Sqlite itself is not fork-safe, as documented in
https://www.sqlite.org/howtocorrupt.html section 2.6. Any databases
that are inherited from the parent process are unsafe to properly
close and may impact either the parent or the child and potentially
lead to database corruption.

In this commit, a pre-fork callback `prepare_to_fork!` is introduced
for the connection pools and adapters to take any necessary actions
before forking. The callback is only implemented by the SQLite3Adapter
which now invokes `disconnect!` to close all open prepared statements
and database connections.

As a side effect, the parent process will end up having to re-open
database connections if it continues to do work, which may be a small
performance overhead for some use cases, but is necessary in order to
prevent database corruption.

See rails/solid_queue#324 for examples of
the type of corruption that can occur.
flavorjones added a commit to flavorjones/rails that referenced this issue Sep 14, 2024
Sqlite itself is not fork-safe, as documented in
https://www.sqlite.org/howtocorrupt.html section 2.6. Any databases
that are inherited from the parent process are unsafe to properly
close and may impact either the parent or the child and potentially
lead to database corruption.

In this commit, a pre-fork callback `prepare_to_fork!` is introduced
for the connection pools and adapters to take any necessary actions
before forking. The callback is only implemented by the SQLite3Adapter
which now invokes `disconnect!` to close all open prepared statements
and database connections.

As a side effect, the parent process will end up having to re-open
database connections if it continues to do work, which may be a small
performance overhead for some use cases, but is necessary in order to
prevent database corruption.

See rails/solid_queue#324 for examples of
the type of corruption that can occur.
@flavorjones
Copy link
Member

See rails/rails#52931 which should address at least one of the issues discussed in this thread (fork-safety). I'd love to get some feedback on it!

flavorjones added a commit to flavorjones/rails that referenced this issue Sep 15, 2024
Sqlite itself is not fork-safe, as documented in
https://www.sqlite.org/howtocorrupt.html section 2.6. Any databases
that are inherited from the parent process are unsafe to properly
close and may impact either the parent or the child and potentially
lead to database corruption.

In this commit, a pre-fork callback `prepare_to_fork!` is introduced
for the connection pools and adapters to take any necessary actions
before forking. The callback is only implemented by the SQLite3Adapter
which now invokes `disconnect!` to close all open prepared statements
and database connections.

As a side effect, the parent process will end up having to re-open
database connections if it continues to do work, which may be a small
performance overhead for some use cases, but is necessary in order to
prevent database corruption.

See rails/solid_queue#324 for examples of
the type of corruption that can occur.
@flavorjones
Copy link
Member

flavorjones commented Sep 16, 2024

Changed direction, here's the latest plan, I'd love feedback:

@flavorjones
Copy link
Member

@andycroll @marcoroth @fractaledmind I just cut a release candidate of sqlite3-ruby with the fork-safety changes from sparklemotion/sqlite3-ruby#558:

https://github.com/sparklemotion/sqlite3-ruby/releases/tag/v2.1.0.rc1

It's an invasive change, it's been a hard issue to reproduce, and it's challenging to test every possible scenario ... so I would really like to have some folks use it and see if we can find problems and/or build confidence.

I've tried out the solid_queue_bughunt repo and it seems like it's working OK (and I can see the warning messages from sqlite3-ruby in the log which means it's doing something ✔). But the more scenarios we can test with the better. If you could just drop a note here if you've been able to test (or if you intend to test), I would ❤️ you forever.

@flavorjones
Copy link
Member

Released https://github.com/sparklemotion/sqlite3-ruby/releases/tag/v2.1.0.rc2 addressing a performance regression in rc1.

@adrienpoly
Copy link

I've tried out the solid_queue_bughunt repo and it seems like it's working OK (and I can see the warning messages from sqlite3-ruby in the log which means it's doing something ✔). But the more scenarios we can test with the better. If you could just drop a note here if you've been able to test (or if you intend to test), I would ❤️ you forever.

FYI I have upgraded rubyvideo.dev with this latest version(adrienpoly/rubyvideo@71ece9b). It is now live in prod. So fare everything looks perfect.

@npezza93
Copy link

Been using the new sqlite rc version and havent had any issues. But when running bin/jobs start i'm seeing:

/Users/nick/.rbenv/versions/3.3.5/lib/ruby/gems/3.3.0/gems/sqlite3-2.1.0.rc2-arm64-darwin/lib/sqlite3/fork_safety.rb:41: warning: Writable sqlite database connection(s) were inherited from a forked process. This is unsafe and the connections are being closed to prevent possible data corruption. Please close writable sqlite database connections before forking.

Should i be seeing that warning with this config?

I have a database config of

default: &default
  adapter: sqlite3
  pool: <%= ENV.fetch("RAILS_MAX_THREADS") { 5 } %>
  timeout: 5000

development:
  primary:
    <<: *default
    database: storage/dev.sqlite3

And a queue.yml of

default: &default
  dispatchers:
    - polling_interval: 1
      batch_size: 500
  workers:
    - queues: "*"
      threads: 3
      processes: <%= ENV.fetch("JOB_CONCURRENCY", 2) %>
      polling_interval: 0.1

development:
  <<: *default

test:
  <<: *default

production:
  <<: *default

@flavorjones
Copy link
Member

@npezza93 I think it's normal to see this message. I'm not a solid queue expert, but I believe the supervisor process hits the database (as part of active record bootstrapping if nothing else) before forking, and that would result in a warning on your tty. Someone who knows it better might be able to tell me how I'm wrong.

Sqlite3-ruby maintainers discussed whether or not to emit warnings, but we decided to err on the side of overcommunicating, at least in the RC and probably the first final release of 2.1.0.

@dhh
Copy link
Member

dhh commented Sep 24, 2024

@flavorjones Maybe we can set a flag for Rails 8 to suppress that warning? Because would be nice if out of the box there is nothing alarming posted about the default setup. Especially since we still have some ways to go to reassure folks that sqlite is good and safe in production.

@flavorjones
Copy link
Member

@dhh Yep. We can add a method SQLite3::ForkSafety.suppress_warnings! that will hush it up, and it can be called in the sqlite3 adapter. Hang tight.

@flavorjones
Copy link
Member

See sparklemotion/sqlite3-ruby#566

@flavorjones
Copy link
Member

Also see rails/rails#53033

@dhh
Copy link
Member

dhh commented Sep 24, 2024

Perfect, @flavorjones 👌

@rosa
Copy link
Member

rosa commented Sep 25, 2024

I believe the supervisor process hits the database (as part of active record bootstrapping if nothing else) before forking

Yes, that's exactly right! It uses the DB to register itself, which happens before forking. It's useful to have the supervisor registered before because, in that way, the other processes can register themselves knowing their supervisor_id (from registering the supervisor).

Also, suppress the warnings related to forking with open writable connections, despite the lost
memory per-connection.

I haven't had time in the last few days, but I hope to address this in Solid Queue as well, closing the connections before forking.

@northeastprince
Copy link
Contributor

Does sparklemotion/sqlite3-ruby#558 close this?

@dhh
Copy link
Member

dhh commented Sep 29, 2024

Yes.

@dhh dhh closed this as completed Sep 29, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

10 participants