V2.0.0-beta.1 sqlite error

Bug
1

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)"}
2

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":{}}}
3

Thanks for the report!

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

4

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\""}
1 Like
5

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

Screen Shot 2021-10-26 at 2.14.45 PM
Screen Shot 2021-10-26 at 2.14.45 PM1878×1984 150 KB 

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
6

I had to start from scratch on my library with 2.0.0-beta1 and seeing lots of SqliteError: SQLITE_BUSY: database is locked. The number of assets on UI is increasing, however. Should I worry I might be missing lots of photos/videos?

7

I left it scanning 100+K assets overnight and it crashed. :frowning: What is the easiest and most reliable way to make sure everything is scanned? My plan: let it finish, then Rebuild (slow) from UI again.

8

“restart scan” seem to pickup stuff that may have been missed… be careful with “rebuild”, that feature is completely broken in the current alpha, not sure when it started being broken though.

9

Thanks - it looks completed (or very near completion) after restart and few more hours of work. Whenever I add new media to PS, it seems to pick it up rather slow with “Restart sync”. And having to do ./photostructure sync /path/to/directory/ is a bit not “wife friendly”… If you know what I mean. :slight_smile:

K

10

New media should be picked up automatically, without the need for manual intervention (no need to “restart sync”) but maybe there is some new bug or yet-to-be-release bug fix that’s impacting you. That would be for @mrm to figure out :slight_smile:

The Wife Acceptance Factor is critical for the success of all technologies :slight_smile: