V2.0.0-beta.1 sqlite error

This is on v2.0.0-beta1 on UNRAID - I noticed from the “about” page that the sync has a status of “syncing” for the last 12+ hours seemingly not doing anything. Looking in the logs, I am seeing hundreds of SQLITE_BUSY errors.

(I don’t know that this is a new problem with v2.0.0-beta1 though, I may just not have noticed since the progress panel disappeared with v2.0.0-alpha)

sync-file-96-001.log:{"ts":1635216786497,"l":"error","ctx":"DbRetries","msg":"Caught db error. Retrying in 521ms.","meta":"SqliteError: SQLITE_BUSY: database is locked\nSqliteError: database is locked\n    at /ps/app/bin/sync-file.js:9:730963\n    at Function.<anonymous> (/ps/app/bin/sync-file.js:9:752632)\n    at Function.sqliteTransaction (/ps/app/node_modules/better-sqlite3/lib/methods/transaction.js:65:24)\n    at /ps/app/bin/sync-file.js:9:752642\n    at Object.t.handleDbRetries (/ps/app/bin/sync-file.js:9:733023)"}
sync-file-96-001.log:{"ts":1635216806497,"l":"error","ctx":"DbRetries","msg":"Caught db error. Retrying in 1102ms.","meta":"SqliteError: SQLITE_BUSY: database is locked\nSqliteError: database is locked\n    at /ps/app/bin/sync-file.js:9:730963\n    at Function.<anonymous> (/ps/app/bin/sync-file.js:9:752632)\n    at Function.sqliteTransaction (/ps/app/node_modules/better-sqlite3/lib/methods/transaction.js:65:24)\n    at /ps/app/bin/sync-file.js:9:752642\n    at Object.t.handleDbRetries (/ps/app/bin/sync-file.js:9:733023)"}

Also found these errors while trying to figure out why asset rotations are not working… Not very helpful error :slight_smile:

root@Tower:/mnt/user/appdata/photostructure/logs/2021-10-26# cat web-42-001.log
{"ts":1635267749691,"l":"error","ctx":"DbRetries","msg":"Caught db error. Not retrying.","meta":{"cause":{}}}
{"ts":1635267753271,"l":"error","ctx":"DbRetries","msg":"Caught db error. Not retrying.","meta":{"cause":{}}}
{"ts":1635267757004,"l":"error","ctx":"DbRetries","msg":"Caught db error. Not retrying.","meta":{"cause":{}}}
{"ts":1635267760722,"l":"error","ctx":"DbRetries","msg":"Caught db error. Not retrying.","meta":{"cause":{}}}
{"ts":1635267764491,"l":"error","ctx":"DbRetries","msg":"Caught db error. Not retrying.","meta":{"cause":{}}}
{"ts":1635267779191,"l":"error","ctx":"DbRetries","msg":"Caught db error. Not retrying.","meta":{"cause":{}}}
{"ts":1635267779650,"l":"error","ctx":"DbRetries","msg":"Caught db error. Not retrying.","meta":{"cause":{}}}
{"ts":1635267780044,"l":"error","ctx":"DbRetries","msg":"Caught db error. Not retrying.","meta":{"cause":{}}}
{"ts":1635267782931,"l":"error","ctx":"DbRetries","msg":"Caught db error. Not retrying.","meta":{"cause":{}}}
{"ts":1635267783413,"l":"error","ctx":"DbRetries","msg":"Caught db error. Not retrying.","meta":{"cause":{}}}

Thanks for the report!

Can you set PS_LOG_SQL=1 and retry? That may explain what’s going on there.

Done. I now see a ton of “errors”, but my guess those are not really errors? Just the SQL logged? So now it’s the proverbial needle in the haystack.

{"ts":1635270212908,"l":"error","ctx":"DbRequest","msg":"run(): insert into `Heartbeat` (`createdAt`, `name`, `updatedAt`) values (1635270212907, \"ping\", 1635270212907) ON CONFLICT (name) DO UPDATE SET updatedAt=excluded.updatedAt"}
{"ts":1635270212908,"l":"error","ctx":"DbRequest","msg":"get(): select * from `Heartbeat` where `name` = \"ping\""}
{"ts":1635270247556,"l":"error","ctx":"DbRequest","msg":"run(): insert into `Heartbeat` (`createdAt`, `name`, `updatedAt`) values (1635270247556, \"ping\", 1635270247556) ON CONFLICT (name) DO UPDATE SET updatedAt=excluded.updatedAt"}
{"ts":1635270247557,"l":"error","ctx":"DbRequest","msg":"get(): select * from `Heartbeat` where `name` = \"ping\""}

I tried rotating an asset again… Captured the error in the toast as well as a flurry of “errors” from logtail.

2021-10-26T18:20:23.914Z web-42 error DbRequest all(): select * from `Tag` where `parentId` is null order by COALESCE(ordinal, _path) COLLATE NOCASE
2021-10-26T18:20:24.035Z web-42 error DbRequest get(): select * from `Asset` where `shown` = 1 and `id` = 14939
2021-10-26T18:20:24.040Z web-42 error DbRequest get(): select * from `AssetFile` where `assetId` = 14939 and `shown` = 1
2021-10-26T18:20:24.044Z web-42 error DbRequest all(): select `id` as `assetId`, `updateCount` as `v` from `Asset` where `Asset`.`shown` = 1 and `Asset`.`hidden` = 0 and `Asset`.`excludedAt` is null and `Asset`.`deletedAt` is null and `capturedAtLocal` = 2019071612391500 order by `assetId` asc
2021-10-26T18:20:24.046Z web-42 error DbRequest get(): select `id` as `assetId`, `updateCount` as `v` from `Asset` where `Asset`.`shown` = 1 and `Asset`.`hidden` = 0 and `Asset`.`excludedAt` is null and `Asset`.`deletedAt` is null and `capturedAtLocal` < 2019071612391500 order by `capturedAtLocal` desc, `assetId` desc
2021-10-26T18:20:24.047Z web-42 error DbRequest get(): select `id` as `assetId`, `updateCount` as `v` from `Asset` where `Asset`.`shown` = 1 and `Asset`.`hidden` = 0 and `Asset`.`excludedAt` is null and `Asset`.`deletedAt` is null and `capturedAtLocal` > 2019071612391500 order by `capturedAtLocal` asc, `assetId` asc
2021-10-26T18:20:24.130Z web-42 error DbRequest get(): select * from `Asset` where `shown` = 1 and `id` = 14939
2021-10-26T18:20:24.130Z web-42 error DbRequest get(): select * from `AssetFile` where `assetId` = 14939 and `shown` = 1
2021-10-26T18:20:24.131Z web-42 error DbRequest all(): select `id` as `assetId`, `updateCount` as `v` from `Asset` where `Asset`.`shown` = 1 and `Asset`.`hidden` = 0 and `Asset`.`excludedAt` is null and `Asset`.`deletedAt` is null and `capturedAtLocal` = 2019071612391500 order by `assetId` asc
2021-10-26T18:20:24.131Z web-42 error DbRequest get(): select `id` as `assetId`, `updateCount` as `v` from `Asset` where `Asset`.`shown` = 1 and `Asset`.`hidden` = 0 and `Asset`.`excludedAt` is null and `Asset`.`deletedAt` is null and `capturedAtLocal` < 2019071612391500 order by `capturedAtLocal` desc, `assetId` desc
2021-10-26T18:20:24.132Z web-42 error DbRequest get(): select `id` as `assetId`, `updateCount` as `v` from `Asset` where `Asset`.`shown` = 1 and `Asset`.`hidden` = 0 and `Asset`.`excludedAt` is null and `Asset`.`deletedAt` is null and `capturedAtLocal` > 2019071612391500 order by `capturedAtLocal` asc, `assetId` asc
2021-10-26T18:20:26.576Z sync-620 error DbRequest run(): insert into `Heartbeat` (`createdAt`, `name`, `updatedAt`) values (1635272426576, "ping", 1635272426576) ON CONFLICT (name) DO UPDATE SET updatedAt=excluded.updatedAt
2021-10-26T18:20:26.576Z sync-620 error DbRequest get(): select * from `Heartbeat` where `name` = "ping"
2021-10-26T18:20:28.922Z web-42 error DbRequest run(): insert into `Heartbeat` (`createdAt`, `name`, `updatedAt`) values (1635272428921, "ping", 1635272428921) ON CONFLICT (name) DO UPDATE SET updatedAt=excluded.updatedAt
2021-10-26T18:20:28.923Z web-42 error DbRequest get(): select * from `Heartbeat` where `name` = "ping"
2021-10-26T18:20:32.829Z web-42 error DbRequest get(): select * from `Asset` where `shown` = 1 and `id` = 14939
2021-10-26T18:20:32.830Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("false", 14939, 1635272432829, "hidden")
2021-10-26T18:20:32.830Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 221
2021-10-26T18:20:32.830Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("null", 14939, 1635272432829, "excludedAt")
2021-10-26T18:20:32.831Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 222
2021-10-26T18:20:32.831Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("null", 14939, 1635272432829, "deletedAt")
2021-10-26T18:20:32.831Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 223
2021-10-26T18:20:32.832Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("0", 14939, 1635272432829, "rating")
2021-10-26T18:20:32.832Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 224
2021-10-26T18:20:32.832Z web-42 error DbRequest all(): select `AssetFile`.* from `AssetFile` inner join `Asset` on `Asset`.`id` = `AssetFile`.`assetId` where `Asset`.`id` = 14939
2021-10-26T18:20:33.352Z web-42 error DbRequest all(): select `tagId` from `AssetTag` where `assetId` = 14939
2021-10-26T18:20:33.353Z web-42 error DbRequest run(): insert into `ChangedTag` (`tagId`, `updatedAt`) select 14 as `tagId`, 1635272433352 as `updatedAt` union all select 178 as `tagId`, 1635272433352 as `updatedAt` union all select 305 as `tagId`, 1635272433352 as `updatedAt` union all select 819 as `tagId`, 1635272433352 as `updatedAt` union all select 820 as `tagId`, 1635272433352 as `updatedAt` union all select 821 as `tagId`, 1635272433352 as `updatedAt` union all select 1293 as `tagId`, 1635272433352 as `updatedAt` where true on conflict (`tagId`) do update set `updatedAt` = 1635272433352
2021-10-26T18:20:33.354Z web-42 error DbRequest run(): update `Asset` set `id` = 14939, `capturedAtLocal` = 2019071612391500, `shown` = 1, `hidden` = 0, `rating` = 0, `version` = 3, `createdAt` = 1634845990689, `updatedAt` = 1635272433354, `updateCount` = 13, `deletedAt` = null, `durationMs` = null, `excludedAt` = null where `id` = 14939
2021-10-26T18:20:33.363Z web-42 error DbRequest run(): insert into `AdvisoryLock` (`acquired`, `createdAt`, `lockId`, `name`) values (0, 1635272433362, "WnaVvngZt-1n", "asset:14939")
2021-10-26T18:20:33.363Z web-42 error DbRequest run(): update `AdvisoryLock` set `acquired` = 1 where `lockId` = "WnaVvngZt-1n"
2021-10-26T18:20:33.396Z web-42 error DbRequest all(): select * from `AssetFile` where `assetId` = 14939
2021-10-26T18:20:33.478Z web-42 error DbRequest run(): delete from `AdvisoryLock` where `lockId` = "WnaVvngZt-1n"
2021-10-26T18:20:33.478Z web-42 error DbRetries Caught db error. Not retrying. { cause: {} }
2021-10-26T18:20:37.000Z web-42 error DbRequest get(): select * from `Asset` where `shown` = 1 and `id` = 14939
2021-10-26T18:20:37.004Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("false", 14939, 1635272437002, "hidden")
2021-10-26T18:20:37.005Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 225
2021-10-26T18:20:37.007Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("null", 14939, 1635272437002, "excludedAt")
2021-10-26T18:20:37.008Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 226
2021-10-26T18:20:37.010Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("null", 14939, 1635272437002, "deletedAt")
2021-10-26T18:20:37.012Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 227
2021-10-26T18:20:37.014Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("0", 14939, 1635272437002, "rating")
2021-10-26T18:20:37.015Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 228
2021-10-26T18:20:37.017Z web-42 error DbRequest all(): select `AssetFile`.* from `AssetFile` inner join `Asset` on `Asset`.`id` = `AssetFile`.`assetId` where `Asset`.`id` = 14939
2021-10-26T18:20:37.229Z web-42 error DbRequest all(): select `tagId` from `AssetTag` where `assetId` = 14939
2021-10-26T18:20:37.229Z web-42 error DbRequest run(): insert into `ChangedTag` (`tagId`, `updatedAt`) select 14 as `tagId`, 1635272437229 as `updatedAt` union all select 178 as `tagId`, 1635272437229 as `updatedAt` union all select 305 as `tagId`, 1635272437229 as `updatedAt` union all select 819 as `tagId`, 1635272437229 as `updatedAt` union all select 820 as `tagId`, 1635272437229 as `updatedAt` union all select 821 as `tagId`, 1635272437229 as `updatedAt` union all select 1293 as `tagId`, 1635272437229 as `updatedAt` where true on conflict (`tagId`) do update set `updatedAt` = 1635272437229
2021-10-26T18:20:37.231Z web-42 error DbRequest run(): update `Asset` set `id` = 14939, `capturedAtLocal` = 2019071612391500, `shown` = 1, `hidden` = 0, `rating` = 0, `version` = 3, `createdAt` = 1634845990689, `updatedAt` = 1635272437230, `updateCount` = 14, `deletedAt` = null, `durationMs` = null, `excludedAt` = null where `id` = 14939
2021-10-26T18:20:37.236Z web-42 error DbRequest run(): insert into `AdvisoryLock` (`acquired`, `createdAt`, `lockId`, `name`) values (0, 1635272437236, "WnaVvngZt-1q", "asset:14939")
2021-10-26T18:20:37.236Z web-42 error DbRequest run(): update `AdvisoryLock` set `acquired` = 1 where `lockId` = "WnaVvngZt-1q"
2021-10-26T18:20:37.256Z web-42 error DbRequest all(): select * from `AssetFile` where `assetId` = 14939
2021-10-26T18:20:37.261Z web-42 error DbRequest run(): delete from `AdvisoryLock` where `lockId` = "WnaVvngZt-1q"
2021-10-26T18:20:37.261Z web-42 error DbRetries Caught db error. Not retrying. { cause: {} }
2021-10-26T18:20:40.777Z web-42 error DbRequest get(): select * from `Asset` where `shown` = 1 and `id` = 14939
2021-10-26T18:20:40.780Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("false", 14939, 1635272440779, "hidden")
2021-10-26T18:20:40.780Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 229
2021-10-26T18:20:40.780Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("null", 14939, 1635272440779, "excludedAt")
2021-10-26T18:20:40.780Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 230
2021-10-26T18:20:40.781Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("null", 14939, 1635272440779, "deletedAt")
2021-10-26T18:20:40.781Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 231
2021-10-26T18:20:40.781Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("0", 14939, 1635272440779, "rating")
2021-10-26T18:20:40.782Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 232
2021-10-26T18:20:40.782Z web-42 error DbRequest all(): select `AssetFile`.* from `AssetFile` inner join `Asset` on `Asset`.`id` = `AssetFile`.`assetId` where `Asset`.`id` = 14939
2021-10-26T18:20:40.975Z web-42 error DbRequest all(): select `tagId` from `AssetTag` where `assetId` = 14939
2021-10-26T18:20:40.975Z web-42 error DbRequest run(): insert into `ChangedTag` (`tagId`, `updatedAt`) select 14 as `tagId`, 1635272440975 as `updatedAt` union all select 178 as `tagId`, 1635272440975 as `updatedAt` union all select 305 as `tagId`, 1635272440975 as `updatedAt` union all select 819 as `tagId`, 1635272440975 as `updatedAt` union all select 820 as `tagId`, 1635272440975 as `updatedAt` union all select 821 as `tagId`, 1635272440975 as `updatedAt` union all select 1293 as `tagId`, 1635272440975 as `updatedAt` where true on conflict (`tagId`) do update set `updatedAt` = 1635272440975
2021-10-26T18:20:40.976Z web-42 error DbRequest run(): update `Asset` set `id` = 14939, `capturedAtLocal` = 2019071612391500, `shown` = 1, `hidden` = 0, `rating` = 0, `version` = 3, `createdAt` = 1634845990689, `updatedAt` = 1635272440975, `updateCount` = 15, `deletedAt` = null, `durationMs` = null, `excludedAt` = null where `id` = 14939
2021-10-26T18:20:40.981Z web-42 error DbRequest run(): insert into `AdvisoryLock` (`acquired`, `createdAt`, `lockId`, `name`) values (0, 1635272440980, "WnaVvngZt-1s", "asset:14939")
2021-10-26T18:20:40.981Z web-42 error DbRequest run(): update `AdvisoryLock` set `acquired` = 1 where `lockId` = "WnaVvngZt-1s"
2021-10-26T18:20:40.997Z web-42 error DbRequest all(): select * from `AssetFile` where `assetId` = 14939
2021-10-26T18:20:41.004Z web-42 error DbRequest run(): delete from `AdvisoryLock` where `lockId` = "WnaVvngZt-1s"
2021-10-26T18:20:41.005Z web-42 error DbRetries Caught db error. Not retrying. { cause: {} }
2021-10-26T18:20:41.576Z sync-620 error DbRequest run(): insert into `Heartbeat` (`createdAt`, `name`, `updatedAt`) values (1635272441576, "ping", 1635272441576) ON CONFLICT (name) DO UPDATE SET updatedAt=excluded.updatedAt
2021-10-26T18:20:41.576Z sync-620 error DbRequest get(): select * from `Heartbeat` where `name` = "ping"
2021-10-26T18:20:44.519Z web-42 error DbRequest get(): select * from `Asset` where `shown` = 1 and `id` = 14939
2021-10-26T18:20:44.522Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("false", 14939, 1635272444521, "hidden")
2021-10-26T18:20:44.522Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 233
2021-10-26T18:20:44.522Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("null", 14939, 1635272444522, "excludedAt")
2021-10-26T18:20:44.523Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 234
2021-10-26T18:20:44.523Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("null", 14939, 1635272444522, "deletedAt")
2021-10-26T18:20:44.523Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 235
2021-10-26T18:20:44.523Z web-42 error DbRequest run(): insert into `AssetRevision` (`_priorValueJson`, `assetId`, `createdAt`, `field`) values ("0", 14939, 1635272444522, "rating")
2021-10-26T18:20:44.524Z web-42 error DbRequest get(): select * from `AssetRevision` where `id` = 236
2021-10-26T18:20:44.524Z web-42 error DbRequest all(): select `AssetFile`.* from `AssetFile` inner join `Asset` on `Asset`.`id` = `AssetFile`.`assetId` where `Asset`.`id` = 14939
2021-10-26T18:20:44.717Z web-42 error DbRequest all(): select `tagId` from `AssetTag` where `assetId` = 14939
2021-10-26T18:20:44.718Z web-42 error DbRequest run(): insert into `ChangedTag` (`tagId`, `updatedAt`) select 14 as `tagId`, 1635272444718 as `updatedAt` union all select 178 as `tagId`, 1635272444718 as `updatedAt` union all select 305 as `tagId`, 1635272444718 as `updatedAt` union all select 819 as `tagId`, 1635272444718 as `updatedAt` union all select 820 as `tagId`, 1635272444718 as `updatedAt` union all select 821 as `tagId`, 1635272444718 as `updatedAt` union all select 1293 as `tagId`, 1635272444718 as `updatedAt` where true on conflict (`tagId`) do update set `updatedAt` = 1635272444718
2021-10-26T18:20:44.719Z web-42 error DbRequest run(): update `Asset` set `id` = 14939, `capturedAtLocal` = 2019071612391500, `shown` = 1, `hidden` = 0, `rating` = 0, `version` = 3, `createdAt` = 1634845990689, `updatedAt` = 1635272444718, `updateCount` = 16, `deletedAt` = null, `durationMs` = null, `excludedAt` = null where `id` = 14939
2021-10-26T18:20:44.734Z web-42 error DbRequest run(): insert into `AdvisoryLock` (`acquired`, `createdAt`, `lockId`, `name`) values (0, 1635272444733, "WnaVvngZt-1u", "asset:14939")
2021-10-26T18:20:44.739Z web-42 error DbRequest run(): update `AdvisoryLock` set `acquired` = 1 where `lockId` = "WnaVvngZt-1u"
2021-10-26T18:20:44.775Z web-42 error DbRequest all(): select * from `AssetFile` where `assetId` = 14939