Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[Bug]: #1971

Closed
patrickrobbins opened this issue Jul 26, 2023 · 8 comments
Closed

[Bug]: #1971

patrickrobbins opened this issue Jul 26, 2023 · 8 comments
Labels
bug Something isn't working

Comments

@patrickrobbins
Copy link

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

  1. unknown

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
@patrickrobbins patrickrobbins added the bug Something isn't working label Jul 26, 2023
@patrickrobbins
Copy link
Author

I have set the logging level to debug to see if I can capture a future crash.

@advplyr
Copy link
Owner

advplyr commented Jul 26, 2023

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.

@patrickrobbins
Copy link
Author

I use unraid, and it looks like it is not persisting the logs past a container restart. I will investigate more.

advplyr added a commit that referenced this issue Jul 26, 2023
@advplyr
Fix:Sync local media progress when library item not found #1971
8be1651
@advplyr
Copy link
Owner

advplyr commented Jul 26, 2023

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.

@advplyr advplyr added the awaiting release Issue is resolved and will be in the next release label Jul 26, 2023
@patrickrobbins
Copy link
Author

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.

@patrickrobbins
Copy link
Author

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

@selfhost-alt
Copy link
Contributor

I've been having crashes with a very similar error, which seems to be caused by two of my users' apps uploading progress.

Log Dump 

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 <redacted> (SocketAuthority.js:162)
[2023-09-08 04:30:35] DEBUG: [MeController] syncLocalMediaProgress local progress is more recent - updating 7e333b00-12b9-46af-b53b-a629455cacd8 (MeController.js:209)
[2023-09-08 04:30:35] DEBUG: [MeController] syncLocalMediaProgress server updates = 1, local updates = 0 (MeController.js:232)
[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)
[2023-09-08 04:30:35] DEBUG: [PlaybackSessionManager] Updating progress for "Eragon " with current time 57406.590087864 (previously 57406.590087864) (PlaybackSessionManager.js:165)
node:internal/process/promises:279
            triggerUncaughtException(err, true /* fromPromise */);
            ^

Error
    at Database.<anonymous> (/node_modules/sequelize/lib/dialects/sqlite/query.js:185:27)
    at /node_modules/sequelize/lib/dialects/sqlite/query.js:183:50
    at new Promise (<anonymous>)
    at Query.run (/node_modules/sequelize/lib/dialects/sqlite/query.js:183:12)
    at /node_modules/sequelize/lib/sequelize.js:315:28
    at async SQLiteQueryInterface.insert (/node_modules/sequelize/lib/dialects/abstract/query-interface.js:308:21)
    at async PlaybackSession.save (/node_modules/sequelize/lib/model.js:2490:35)
    at async Function.create (/node_modules/sequelize/lib/model.js:1362:12)
    at async PlaybackSessionManager.syncLocalSession (/server/managers/PlaybackSessionManager.js:142:7)
    at async PlaybackSessionManager.syncLocalSessionRequest (/server/managers/PlaybackSessionManager.js:192:20) {
  name: 'SequelizeUniqueConstraintError',
  errors: [
    ValidationErrorItem {
      message: 'id must be unique',
      type: 'unique violation',
      path: 'id',
      value: 'bec9d4e7-ca0c-48b6-b2c8-226d67d3e1d4',
      origin: 'DB',
      instance: playbackSession {
        dataValues: {
          id: 'bec9d4e7-ca0c-48b6-b2c8-226d67d3e1d4',
          mediaItemId: 'cec8628a-931e-4520-9a6d-59fdd3c30b27',
          mediaItemType: 'book',
          libraryId: '471fd0c2-1d48-4dae-906e-38e5644d968c',
          displayTitle: 'Eragon ',
          displayAuthor: 'Christopher Paolini',
          duration: 59152.82925,
          playMethod: 3,
          mediaPlayer: 'AVPlayer',
          startTime: 0,
          currentTime: 57406.590087864,
          serverVersion: '2.3.3',
          createdAt: 2023-09-07T10:03:36.289Z,
          updatedAt: 2023-09-08T11:30:35.711Z,
          userId: '31185470-e799-47f5-8bb1-ba15cdc7d66b',
          deviceId: '1b97de17-a453-4021-b35f-441b8e4299bb',
          timeListening: 23190.293407678604,
          coverPath: 'file:///var/mobile/Containers/Data/Application/664C2948-B9EE-462D-8D96-0FC8DFC104B0/Documents/c8e53379-33e5-4456-9838-b66ed42b87de/cover.jpg',
          mediaMetadata: BookMetadata {
            title: 'Eragon ',
            subtitle: 'Inheritance, Book 1',
            authors: [Array],
            narrators: [Array],
            series: [],
            genres: [Array],
            publishedYear: '2007',
            publishedDate: null,
            publisher: 'Listening Library',
            description: 'Don’t miss the latest book from the author of Eragon : The Fork, the Witch, and the Worm: Tales from Alagaësia! Perfect for fans of Lord of the Rings, the New York Times best-selling Inheritance Cycle about the dragon rider Eragon has sold more than 35 million copies and is an international fantasy sensation. Fifteen-year-old Eragon believes he is merely a poor farm boy - until his destiny as a Dragon Rider is revealed. Gifted with only an ancient sword, a loyal dragon, and sage advice from an old storyteller, Eragon is soon swept into a dangerous tapestry of magic, glory, and power. Now, his choices could save - or destroy - the empire. “An authentic work of great talent.” ( The New York Times Book Review) “Christopher Paolini make[s] literary magic with his precocious debut.” ( People) “Unusual, powerful, fresh, and fluid.” ( Booklist, starred) “An auspicious beginning to both career and series.” ( Publishers Weekly) A New York Times best seller. A USA Today best seller. A Wall Street Journal best seller. A Book Sense best seller.',
            isbn: null,
            asin: 'B002UZKL7A',
            language: null,
            explicit: false,
            abridged: false
          },
          date: undefined,
          dayOfWeek: undefined,
          extraData: { libraryItemId: 'c8e53379-33e5-4456-9838-b66ed42b87de' }
        },
        _previousDataValues: {
          id: undefined,
          mediaItemId: undefined,
          mediaItemType: undefined,
          libraryId: undefined,
          displayTitle: undefined,
          displayAuthor: undefined,
          duration: undefined,
          playMethod: undefined,
          mediaPlayer: undefined,
          startTime: undefined,
          currentTime: undefined,
          serverVersion: undefined,
          createdAt: undefined,
          updatedAt: undefined,
          userId: undefined,
          deviceId: undefined,
          timeListening: undefined,
          coverPath: undefined,
          mediaMetadata: undefined,
          extraData: undefined
        },
        uniqno: 1,
        _changed: Set(20) {
          'id',
          'mediaItemId',
          'mediaItemType',
          'libraryId',
          'displayTitle',
          'displayAuthor',
          'duration',
          'playMethod',
          'mediaPlayer',
          'startTime',
          'currentTime',
          'serverVersion',
          'createdAt',
          'updatedAt',
          'userId',
          'deviceId',
          'timeListening',
          'coverPath',
          'mediaMetadata',
          'extraData'
        },
        _options: {
          isNewRecord: true,
          _schema: null,
          _schemaDelimiter: '',
          attributes: undefined,
          include: undefined,
          raw: undefined,
          silent: undefined
        },
        isNewRecord: true
      },
      validatorKey: 'not_unique',
      validatorName: null,
      validatorArgs: []
    }
  ],
  parent: [Error: SQLITE_CONSTRAINT: UNIQUE constraint failed: playbackSessions.id] {
    errno: 19,
    code: 'SQLITE_CONSTRAINT',
    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);'
  },
  original: [Error: SQLITE_CONSTRAINT: UNIQUE constraint failed: playbackSessions.id] {
    errno: 19,
    code: 'SQLITE_CONSTRAINT',
    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);'
  },
  fields: [ 'id' ],
  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);'
}

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?

@advplyr
Copy link
Owner

advplyr commented Sep 9, 2023

Fixed in v2.4.0

Although the latest server version is now 2.4.1. This is for the original issue you can let me know if it is still causing issues on 2.4.1

@advplyr advplyr closed this as completed Sep 9, 2023
@advplyr advplyr removed the awaiting release Issue is resolved and will be in the next release label Sep 9, 2023
@jrglasgow jrglasgow mentioned this issue Feb 14, 2024
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@patrickrobbins @advplyr @selfhost-alt