SQLite queue database corruption

[andycroll]

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]

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]

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

[rosa]

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]

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]

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

[rosa]

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]

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]

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]

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]

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]

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 🤔

• Flush idle database connections rails#31221
• Improve AR connection fork safety rails#31173
• Drop the before_fork/on_worker_boot advice rails#31241

There must be something else going on here.

[fractaledmind]

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]

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]

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]

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.