possible race condition (only seen in dev)

[ksuquix]

I've seen this consistently when doing a scan with several changes, but I have to ^C the dev instance and restart:

21:31:53 system | sending SIGTERM to all processes 21:31:53 css.1 | terminated by SIGINT 21:31:53 typecheck.1 | terminated by SIGINT 21:31:58 worker.1 | [Worker(host:win pid:12291)] Job ModelFileScanJob [2d3b3716-0d42-4ee8-8c41-26f2edb86b91] from DelayedJob(default) with arguments: [{"_aj_globalid"=>"gid://van-dam/ModelFile/6565"}] (id=8127) (queue=default) COMPLETED after 0.2440 21:31:58 system | SIGINT received, starting shutdown 21:31:58 rails.1 | User Count (0.7ms) SELECT COUNT() FROM "users" 21:31:58 worker.1 | [Worker(host:win pid:12291)] Job ModelFileScanJob [969c190e-7c44-4d4d-8b57-9e5e2818a1af] from DelayedJob(default) with arguments: [{"_aj_globalid"=>"gid://van-dam/ModelFile/6566"}] (id=8128) (queue=default) RUNNING 21:31:58 rails.1 | ↳ app/controllers/application_controller.rb:10:in auto_login_single_user' 21:31:58 worker.1 | [Worker(host:win pid:12291)] Job ModelFileScanJob [969c190e-7c44-4d4d-8b57-9e5e2818a1af] from DelayedJob(default) with arguments: [{"_aj_globalid"=>"gid://van-dam/ModelFile/6566"}] (id=8128) (queue=default) COMPLETED after 0.2360 21:31:58 rails.1 | User Load (0.6ms) SELECT "users".* FROM "users" ORDER BY "users"."id" ASC LIMIT ? [["LIMIT", 1]] 21:31:58 worker.1 | [Worker(host:win pid:12291)] Job ModelFileScanJob [e1f0637a-52ed-4c19-8b86-c0997d7aff24] from DelayedJob(default) with arguments: [{"_aj_globalid"=>"gid://van-dam/ModelFile/6567"}] (id=8129) (queue=default) RUNNING 21:31:58 rails.1 | ↳ app/controllers/application_controller.rb:10:in auto_login_single_user' 21:31:58 worker.1 | [Worker(host:win pid:12291)] Job ModelFileScanJob [e1f0637a-52ed-4c19-8b86-c0997d7aff24] from DelayedJob(default) with arguments: [{"_aj_globalid"=>"gid://van-dam/ModelFile/6567"}] (id=8129) (queue=default) COMPLETED after 0.2010 21:31:58 rails.1 | CACHE User Load (0.0ms) SELECT "users". FROM "users" ORDER BY "users"."id" ASC LIMIT ? [["LIMIT", 1]] 21:31:58 worker.1 | [Worker(host:win pid:12291)] 21 jobs processed at 3.2545 j/s, 0 failed 21:31:58 rails.1 | ↳ app/controllers/application_controller.rb:11:in auto_login_single_user' 21:31:58 worker.1 | [Worker(host:win pid:12291)] Exiting... 21:31:58 rails.1 | User Load (0.6ms) SELECT "users".* FROM "users" WHERE "users"."id" = ? ORDER BY "users"."id" ASC LIMIT ? [["id", 1], ["LIMIT", 1]] 21:31:58 worker.1 | [Worker(host:win pid:12291)] Exiting... 21:31:58 rails.1 | ↳ app/controllers/application_controller.rb:11:in auto_login_single_user' 21:31:58 rails.1 | Delayed::Backend::ActiveRecord::Job Count (0.7ms) SELECT COUNT() FROM "delayed_jobs" 21:31:58 rails.1 | ↳ app/controllers/application_controller.rb:21:in `check_scan_status' 21:31:58 rails.1 | Creator Load (0.7ms) SELECT "creators". FROM "creators" ORDER BY "creators"."name" ASC LIMIT ? OFFSET ? [["LIMIT", 12], ["OFFSET", 0]] 2

[Floppy]

I've seen this too and forgot to note it down, normally because I'm debugging something else at the time! Thanks for making the issue. I think it's to do with the SQLite lock, but I'm not sure.

[ksuquix]

I thought the same thing about the lock... I encountered it several times before I noticed the pattern enough to recognize it as a real issue.

I suspect the 4 threads that are running are involved as well, since the scan is running in the background while the browser keeps doing it's thing. (And it most definitely seems like it's running a scan that triggers this).

https://www.sqlite.org/threadsafe.html

[Floppy]

The right solution is probably to abandon sqlite in dev as well, and use postgres. 🤷🏻

[Floppy]

I think some of these SQLite tuning tips that increase concurrency, avoid locks, etc, might help: https://kerkour.com/sqlite-for-servers

[Floppy]

Rails specific: https://fractaledmind.github.io/2023/09/07/enhancing-rails-sqlite-fine-tuning/

[Floppy]

Changing to https://github.com/Betterment/delayed, an optimised version of delayed_job might help too.