Closed patrickrobbins closed 1 year ago
I have set the logging level to debug to see if I can capture a future crash.
Can you capture the logs from the container instead of using the ones from Abs? There is an uncaught exception that isn't going to show up in Abs logs, we need to get the container logs to see it.
I use unraid, and it looks like it is not persisting the logs past a container restart. I will investigate more.
I took another look and I found the issue. There is media progress on your mobile device that is trying to sync with the server but the linked library item no longer exists. The next server release will fix this, otherwise you can try finding the downloaded item on your device that is the problem and removing it.
ok. I had some books but they had issues, so I removed and readded them, so that might be the issue. I have had some issues previously where I click the remove from continue listening and it will remove, but next login it will be back, if that tries to sync that might exacerbate the issue. Thanks for the quick response.
this happened again, and I was able to find the issue in the docker file: I thought that it could have been based on a library item that isn't existing, but reading through it seems to be syncing while playing a file, unless that is a red herring and the app is syncing some items that aren't currently in progress at some point.
{"log":"[2023-08-02 17:58:16] DEBUG: [PlaybackSessionManager] Updating progress for \"The Dresden Files 05.0 - Death Masks\" with current time 25608.999470000002 (previously 25609.575439620003) (PlaybackSessionManager.js:165)\n","stream":"stdout","time":"2023-08-02T17:58:16.939926514Z"}
{"log":"node:internal/process/promises:279\n","stream":"stderr","time":"2023-08-02T17:58:16.94393433Z"}
{"log":" triggerUncaughtException(err, true / fromPromise /);\n","stream":"stderr","time":"2023-08-02T17:58:16.943951742Z"}
{"log":" ^\n","stream":"stderr","time":"2023-08-02T17:58:16.9439557Z"}
{"log":"\n","stream":"stderr","time":"2023-08-02T17:58:16.94395875Z"}
{"log":"Error\n","stream":"stderr","time":"2023-08-02T17:58:16.943961545Z"}
{"log":" at Database.\u003canonymous\u003e (/node_modules/sequelize/lib/dialects/sqlite/query.js:185:27)\n","stream":"stderr","time":"2023-08-02T17:58:16.943964277Z"}
{"log":" at /node_modules/sequelize/lib/dialects/sqlite/query.js:183:50\n","stream":"stderr","time":"2023-08-02T17:58:16.943967238Z"}
{"log":" at new Promise (\u003canonymous\u003e)\n","stream":"stderr","time":"2023-08-02T17:58:16.943970097Z"}
{"log":" at Query.run (/node_modules/sequelize/lib/dialects/sqlite/query.js:183:12)\n","stream":"stderr","time":"2023-08-02T17:58:16.94397293Z"}
{"log":" at /node_modules/sequelize/lib/sequelize.js:315:28\n","stream":"stderr","time":"2023-08-02T17:58:16.9439756Z"}
{"log":" at async SQLiteQueryInterface.insert (/node_modules/sequelize/lib/dialects/abstract/query-interface.js:308:21)\n","stream":"stderr","time":"2023-08-02T17:58:16.943978282Z"}
{"log":" at async PlaybackSession.save (/node_modules/sequelize/lib/model.js:2490:35)\n","stream":"stderr","time":"2023-08-02T17:58:16.94398102Z"}
{"log":" at async Function.create (/node_modules/sequelize/lib/model.js:1362:12)\n","stream":"stderr","time":"2023-08-02T17:58:16.943983721Z"}
{"log":" at async PlaybackSessionManager.syncLocalSession (/server/managers/PlaybackSessionManager.js:142:7)\n","stream":"stderr","time":"2023-08-02T17:58:16.943986391Z"}
{"log":" at async PlaybackSessionManager.syncLocalSessionRequest (/server/managers/PlaybackSessionManager.js:192:20) {\n","stream":"stderr","time":"2023-08-02T17:58:16.944002239Z"}
{"log":" name: 'SequelizeUniqueConstraintError',\n","stream":"stderr","time":"2023-08-02T17:58:16.944006823Z"}
{"log":" errors: [\n","stream":"stderr","time":"2023-08-02T17:58:16.944009647Z"}
{"log":" ValidationErrorItem {\n","stream":"stderr","time":"2023-08-02T17:58:16.944012332Z"}
{"log":" message: 'id must be unique',\n","stream":"stderr","time":"2023-08-02T17:58:16.944014955Z"}
{"log":" type: 'unique violation',\n","stream":"stderr","time":"2023-08-02T17:58:16.944017603Z"}
{"log":" path: 'id',\n","stream":"stderr","time":"2023-08-02T17:58:16.944020236Z"}
{"log":" value: '3edc8a87-e3ce-416f-9858-70e4b3b3d1ac',\n","stream":"stderr","time":"2023-08-02T17:58:16.944022844Z"}
{"log":" origin: 'DB',\n","stream":"stderr","time":"2023-08-02T17:58:16.94402545Z"}
{"log":" instance: playbackSession {\n","stream":"stderr","time":"2023-08-02T17:58:16.94402818Z"}
{"log":" dataValues: {\n","stream":"stderr","time":"2023-08-02T17:58:16.944030795Z"}
{"log":" id: '3edc8a87-e3ce-416f-9858-70e4b3b3d1ac',\n","stream":"stderr","time":"2023-08-02T17:58:16.944033452Z"}
{"log":" mediaItemId: 'b34549ad-a774-4dbe-b7ba-d8b1521f23a7',\n","stream":"stderr","time":"2023-08-02T17:58:16.944036126Z"}
{"log":" mediaItemType: 'book',\n","stream":"stderr","time":"2023-08-02T17:58:16.9440388Z"}
{"log":" libraryId: 'd1661310-ee60-4ea1-94e5-e1fb4af86414',\n","stream":"stderr","time":"2023-08-02T17:58:16.944041423Z"}
{"log":" displayTitle: 'The Dresden Files 05.0 - Death Masks',\n","stream":"stderr","time":"2023-08-02T17:58:16.944044055Z"}
{"log":" displayAuthor: 'Jim Butcher',\n","stream":"stderr","time":"2023-08-02T17:58:16.94404668Z"}
{"log":" duration: 40683.75510300001,\n","stream":"stderr","time":"2023-08-02T17:58:16.944049384Z"}
{"log":" playMethod: 3,\n","stream":"stderr","time":"2023-08-02T17:58:16.944052072Z"}
{"log":" mediaPlayer: 'AVPlayer',\n","stream":"stderr","time":"2023-08-02T17:58:16.944054704Z"}
{"log":" startTime: 0,\n","stream":"stderr","time":"2023-08-02T17:58:16.944057351Z"}
{"log":" currentTime: 26090.893062000003,\n","stream":"stderr","time":"2023-08-02T17:58:16.944059969Z"}
{"log":" serverVersion: '2.3.3',\n","stream":"stderr","time":"2023-08-02T17:58:16.944062589Z"}
{"log":" createdAt: 2023-08-01T22:24:38.439Z,\n","stream":"stderr","time":"2023-08-02T17:58:16.944065189Z"}
{"log":" updatedAt: 2023-08-02T17:58:16.936Z,\n","stream":"stderr","time":"2023-08-02T17:58:16.944067827Z"}
{"log":" userId: 'a101a5a3-b36f-49ff-8ca2-4cf1107ce6a4',\n","stream":"stderr","time":"2023-08-02T17:58:16.944070526Z"}
{"log":" deviceId: '704c37a1-4e41-4303-bfa0-cdb3542c9a89',\n","stream":"stderr","time":"2023-08-02T17:58:16.944073174Z"}
{"log":" timeListening: 2216.28374171257,\n","stream":"stderr","time":"2023-08-02T17:58:16.944075825Z"}
{"log":" coverPath: 'file:///var/mobile/Containers/Data/Application/85E812A1-5164-4801-A596-A9F76A155951/Documents/150ce3fe-51d0-4b6d-9705-c776530cf4d5/cover.jpg',\n","stream":"stderr","time":"2023-08-02T17:58:16.94407897Z"}
{"log":" mediaMetadata: BookMetadata {\n","stream":"stderr","time":"2023-08-02T17:58:16.944081869Z"}
{"log":" title: 'The Dresden Files 05.0 - Death Masks',\n","stream":"stderr","time":"2023-08-02T17:58:16.944084498Z"}
{"log":" subtitle: null,\n","stream":"stderr","time":"2023-08-02T17:58:16.944087123Z"}
{"log":" authors: [Array],\n","stream":"stderr","time":"2023-08-02T17:58:16.944089779Z"}
{"log":" narrators: [],\n","stream":"stderr","time":"2023-08-02T17:58:16.944092504Z"}
{"log":" series: [],\n","stream":"stderr","time":"2023-08-02T17:58:16.944095161Z"}
{"log":" genres: [Array],\n","stream":"stderr","time":"2023-08-02T17:58:16.94409781Z"}
{"log":" publishedYear: null,\n","stream":"stderr","time":"2023-08-02T17:58:16.94410544Z"}
{"log":" publishedDate: null,\n","stream":"stderr","time":"2023-08-02T17:58:16.944108657Z"}
{"log":" publisher: null,\n","stream":"stderr","time":"2023-08-02T17:58:16.944111302Z"}
{"log":" description: null,\n","stream":"stderr","time":"2023-08-02T17:58:16.944113945Z"}
{"log":" isbn: null,\n","stream":"stderr","time":"2023-08-02T17:58:16.944116557Z"}
{"log":" asin: null,\n","stream":"stderr","time":"2023-08-02T17:58:16.944119237Z"}
{"log":" language: null,\n","stream":"stderr","time":"2023-08-02T17:58:16.944121866Z"}
{"log":" explicit: false,\n","stream":"stderr","time":"2023-08-02T17:58:16.944124487Z"}
{"log":" abridged: false\n","stream":"stderr","time":"2023-08-02T17:58:16.944127092Z"}
{"log":" },\n","stream":"stderr","time":"2023-08-02T17:58:16.944129718Z"}
{"log":" date: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944132277Z"}
{"log":" dayOfWeek: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944134832Z"}
{"log":" extraData: { libraryItemId: '150ce3fe-51d0-4b6d-9705-c776530cf4d5' }\n","stream":"stderr","time":"2023-08-02T17:58:16.944137481Z"}
{"log":" },\n","stream":"stderr","time":"2023-08-02T17:58:16.944140266Z"}
{"log":" _previousDataValues: {\n","stream":"stderr","time":"2023-08-02T17:58:16.944142855Z"}
{"log":" id: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944145458Z"}
{"log":" mediaItemId: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944148109Z"}
{"log":" mediaItemType: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944150748Z"}
{"log":" libraryId: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944153364Z"}
{"log":" displayTitle: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944155897Z"}
{"log":" displayAuthor: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944158501Z"}
{"log":" duration: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944161197Z"}
{"log":" playMethod: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944163801Z"}
{"log":" mediaPlayer: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944166388Z"}
{"log":" startTime: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944169023Z"}
{"log":" currentTime: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944171573Z"}
{"log":" serverVersion: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944174096Z"}
{"log":" createdAt: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944176728Z"}
{"log":" updatedAt: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944179334Z"}
{"log":" userId: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944181992Z"}
{"log":" deviceId: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944184614Z"}
{"log":" timeListening: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944187251Z"}
{"log":" coverPath: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.94418991Z"}
{"log":" mediaMetadata: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944192524Z"}
{"log":" extraData: undefined\n","stream":"stderr","time":"2023-08-02T17:58:16.94419514Z"}
{"log":" },\n","stream":"stderr","time":"2023-08-02T17:58:16.944197789Z"}
{"log":" uniqno: 1,\n","stream":"stderr","time":"2023-08-02T17:58:16.944200359Z"}
{"log":" _changed: Set(20) {\n","stream":"stderr","time":"2023-08-02T17:58:16.944203042Z"}
{"log":" 'id',\n","stream":"stderr","time":"2023-08-02T17:58:16.944205659Z"}
{"log":" 'mediaItemId',\n","stream":"stderr","time":"2023-08-02T17:58:16.944208282Z"}
{"log":" 'mediaItemType',\n","stream":"stderr","time":"2023-08-02T17:58:16.944210932Z"}
{"log":" 'libraryId',\n","stream":"stderr","time":"2023-08-02T17:58:16.944217448Z"}
{"log":" 'displayTitle',\n","stream":"stderr","time":"2023-08-02T17:58:16.944220478Z"}
{"log":" 'displayAuthor',\n","stream":"stderr","time":"2023-08-02T17:58:16.944223084Z"}
{"log":" 'duration',\n","stream":"stderr","time":"2023-08-02T17:58:16.944225698Z"}
{"log":" 'playMethod',\n","stream":"stderr","time":"2023-08-02T17:58:16.944228388Z"}
{"log":" 'mediaPlayer',\n","stream":"stderr","time":"2023-08-02T17:58:16.944231017Z"}
{"log":" 'startTime',\n","stream":"stderr","time":"2023-08-02T17:58:16.944233685Z"}
{"log":" 'currentTime',\n","stream":"stderr","time":"2023-08-02T17:58:16.944236317Z"}
{"log":" 'serverVersion',\n","stream":"stderr","time":"2023-08-02T17:58:16.944238911Z"}
{"log":" 'createdAt',\n","stream":"stderr","time":"2023-08-02T17:58:16.944241454Z"}
{"log":" 'updatedAt',\n","stream":"stderr","time":"2023-08-02T17:58:16.944244023Z"}
{"log":" 'userId',\n","stream":"stderr","time":"2023-08-02T17:58:16.9442466Z"}
{"log":" 'deviceId',\n","stream":"stderr","time":"2023-08-02T17:58:16.944249283Z"}
{"log":" 'timeListening',\n","stream":"stderr","time":"2023-08-02T17:58:16.944251892Z"}
{"log":" 'coverPath',\n","stream":"stderr","time":"2023-08-02T17:58:16.944254539Z"}
{"log":" 'mediaMetadata',\n","stream":"stderr","time":"2023-08-02T17:58:16.944257147Z"}
{"log":" 'extraData'\n","stream":"stderr","time":"2023-08-02T17:58:16.944259714Z"}
{"log":" },\n","stream":"stderr","time":"2023-08-02T17:58:16.944262294Z"}
{"log":" _options: {\n","stream":"stderr","time":"2023-08-02T17:58:16.944264857Z"}
{"log":" isNewRecord: true,\n","stream":"stderr","time":"2023-08-02T17:58:16.944267752Z"}
{"log":" _schema: null,\n","stream":"stderr","time":"2023-08-02T17:58:16.944271281Z"}
{"log":" _schemaDelimiter: '',\n","stream":"stderr","time":"2023-08-02T17:58:16.944273949Z"}
{"log":" attributes: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944276586Z"}
{"log":" include: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944279224Z"}
{"log":" raw: undefined,\n","stream":"stderr","time":"2023-08-02T17:58:16.944281843Z"}
{"log":" silent: undefined\n","stream":"stderr","time":"2023-08-02T17:58:16.944284432Z"}
{"log":" },\n","stream":"stderr","time":"2023-08-02T17:58:16.944287052Z"}
{"log":" isNewRecord: true\n","stream":"stderr","time":"2023-08-02T17:58:16.944289604Z"}
{"log":" },\n","stream":"stderr","time":"2023-08-02T17:58:16.944292269Z"}
{"log":" validatorKey: 'not_unique',\n","stream":"stderr","time":"2023-08-02T17:58:16.944294919Z"}
{"log":" validatorName: null,\n","stream":"stderr","time":"2023-08-02T17:58:16.944297559Z"}
{"log":" validatorArgs: []\n","stream":"stderr","time":"2023-08-02T17:58:16.944300152Z"}
{"log":" }\n","stream":"stderr","time":"2023-08-02T17:58:16.944302765Z"}
{"log":" ],\n","stream":"stderr","time":"2023-08-02T17:58:16.944305381Z"}
{"log":" parent: [Error: SQLITE_CONSTRAINT: UNIQUE constraint failed: playbackSessions.id] {\n","stream":"stderr","time":"2023-08-02T17:58:16.944308008Z"}
{"log":" errno: 19,\n","stream":"stderr","time":"2023-08-02T17:58:16.944310676Z"}
{"log":" code: 'SQLITE_CONSTRAINT',\n","stream":"stderr","time":"2023-08-02T17:58:16.944313369Z"}
{"log":" sql: 'INSERT INTO playbackSessions
(id
,mediaItemId
,mediaItemType
,displayTitle
,displayAuthor
,duration
,playMethod
,mediaPlayer
,startTime
,currentTime
,serverVersion
,coverPath
,timeListening
,mediaMetadata
,extraData
,createdAt
,updatedAt
,userId
,deviceId
,libraryId
) VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14,$15,$16,$17,$18,$19,$20);'\n","stream":"stderr","time":"2023-08-02T17:58:16.944316298Z"}
{"log":" },\n","stream":"stderr","time":"2023-08-02T17:58:16.944319435Z"}
{"log":" original: [Error: SQLITE_CONSTRAINT: UNIQUE constraint failed: playbackSessions.id] {\n","stream":"stderr","time":"2023-08-02T17:58:16.944326697Z"}
{"log":" errno: 19,\n","stream":"stderr","time":"2023-08-02T17:58:16.944329872Z"}
{"log":" code: 'SQLITE_CONSTRAINT',\n","stream":"stderr","time":"2023-08-02T17:58:16.944332489Z"}
{"log":" sql: 'INSERT INTO playbackSessions
(id
,mediaItemId
,mediaItemType
,displayTitle
,displayAuthor
,duration
,playMethod
,mediaPlayer
,startTime
,currentTime
,serverVersion
,coverPath
,timeListening
,mediaMetadata
,extraData
,createdAt
,updatedAt
,userId
,deviceId
,libraryId
) VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14,$15,$16,$17,$18,$19,$20);'\n","stream":"stderr","time":"2023-08-02T17:58:16.944335165Z"}
{"log":" },\n","stream":"stderr","time":"2023-08-02T17:58:16.944344807Z"}
{"log":" fields: [ 'id' ],\n","stream":"stderr","time":"2023-08-02T17:58:16.944347627Z"}
{"log":" sql: 'INSERT INTO playbackSessions
(id
,mediaItemId
,mediaItemType
,displayTitle
,displayAuthor
,duration
,playMethod
,mediaPlayer
,startTime
,currentTime
,serverVersion
,coverPath
,timeListening
,mediaMetadata
,extraData
,createdAt
,updatedAt
,userId
,deviceId
,libraryId
) VALUES ($1,$2,$3,$4,$5,$6,$7,$8,$9,$10,$11,$12,$13,$14,$15,$16,$17,$18,$19,$20);'\n","stream":"stderr","time":"2023-08-02T17:58:16.944350362Z"}
{"log":"}\n","stream":"stderr","time":"2023-08-02T17:58:16.944353494Z"}
{"log":"Config /config /metadata\n","stream":"stdout","time":"2023-08-02T20:06:07.738593951Z"}
{"log":"[2023-08-02 20:06:07] INFO: === Starting Server ===\n","stream":"stdout","time":"2023-08-02T20:06:08.0187921Z"}
I've been having crashes with a very similar error, which seems to be caused by two of my users' apps uploading progress.
```
Added | 0 Updated | 0 Missing
[2023-09-08 04:30:20] INFO: [Server] Socket Connected VFE94Lv4DS_aOm7pAAAD
[2023-09-08 04:30:34] DEBUG: [Server] User Online
Specifically, I think these lines probably point to the problem:
[2023-09-08 04:30:35] DEBUG: [PlaybackSessionManager] Inserting new session for "Eragon " (bec9d4e7-ca0c-48b6-b2c8-226d67d3e1d4) (PlaybackSessionManager.js:141)
[2023-09-08 04:30:35] DEBUG: [PlaybackSessionManager] Inserting new session for "Eragon " (bec9d4e7-ca0c-48b6-b2c8-226d67d3e1d4) (PlaybackSessionManager.js:141)
It looks like maybe a race condition in the check for an existing session when multiple syncLocalSession
calls happen very quickly. Not sure if it's the client that's sending a bunch of requests, or perhaps it's some bulk handling of playback updates that's triggering these? Maybe the sqlite queries could be updated to do some sort of upsert, or perhaps this specific sqlite exception could be caught and handled in the same way as when the session already exists?
Describe the issue
Server crashed. restarted docker and worked fine so far. I will try to find how to increase logging levels
Steps to reproduce the issue
here are the logs before and after crash:
{"timestamp":"2023-07-26 11:19:08","source":"Logger.js:114","message":"[Watcher] Initializing watcher for \"AudioBooks\".","levelName":"INFO","level":2} {"timestamp":"2023-07-26 11:19:08","source":"Logger.js:114","message":"Listening on port :80","levelName":"INFO","level":2} {"timestamp":"2023-07-26 11:19:22","source":"Logger.js:114","message":"[Watcher] \"AudioBooks\" Ready","levelName":"INFO","level":2} {"timestamp":"2023-07-26 12:27:14","source":"Logger.js:114","message":"[Server] Socket Connected NuM9CpJnNyIQ9npMAAAB","levelName":"INFO","level":2} {"timestamp":"2023-07-26 12:27:14","source":"Logger.js:126","message":"[MeController] syncLocalMediaProgress invalid local media progress object no library item [object Object]","levelName":"ERROR","level":4} {"timestamp":"2023-07-26 21:24:36","source":"Logger.js:114","message":"=== Starting Server ===","levelName":"INFO","level":2} {"timestamp":"2023-07-26 21:24:36","source":"Logger.js:114","message":"[Server] Init v2.3.3","levelName":"INFO","level":2}
Audiobookshelf version
2.3.3
How are you running audiobookshelf?
Docker