[Bug]: Library fails to scan (hangs indefinitely)

mikehoyle commented 9 months ago

Describe the issue

I have been unable to scan my Audiobooks library recently (new issue, after using Audiobookshelf for a few years). This started repro-ing after I manually deleted the metadata in-app for a few books in order to change their folder structure and re-scan them for better matching.

Now, when I press "Scan" the Task spinner appears, but hangs indefinitely. After a minute or two, I get a "socket disconnected" message (note I am accessing via localhost, no network issues possible). I have let the spinner go for hours, but the scan never completes. There seems to be no log created for the scan attempt in the logs/scans folder. The main program log doesn't seem particularly insightful:

{"timestamp":"2024-02-11 18:00:00.268","source":"Logger.js:105","message":"[LibraryScanner] Starting library scan fc7e64b6-be2f-4d94-9bdf-1cf96ee967c6 for Audiobooks","levelName":"INFO","level":2}
{"timestamp":"2024-02-11 18:01:27.758","source":"Logger.js:105","message":"[SocketAuthority] Socket Connected U2tDWigjW6_AmlCcAAAJ","levelName":"INFO","level":2}
{"timestamp":"2024-02-11 18:01:28.224","source":"Logger.js:105","message":"[SocketAuthority] Socket 5u70Ch1gDCp4WBNjAAAD disconnected from client \"root\" after 11383264ms (Reason: transport error)","levelName":"INFO","level":2}
{"timestamp":"2024-02-11 18:01:28.313","source":"Logger.js:105","message":"[SocketAuthority] Socket Connected 9M8r7UeML-PQdVPGAAAL","levelName":"INFO","level":2}
{"timestamp":"2024-02-11 18:01:37.340","source":"Logger.js:105","message":"[SocketAuthority] Socket 8Q8VIwqrfleIHmpiAAAB disconnected from client \"root\" after 11393278ms (Reason: ping timeout)","levelName":"INFO","level":2}
{"timestamp":"2024-02-11 18:03:05.295","source":"Logger.js:105","message":"=== Starting Server ===","levelName":"INFO","level":2}
{"timestamp":"2024-02-11 18:03:05.296","source":"Logger.js:105","message":"[Server] Init v2.7.2","levelName":"INFO","level":2}
{"timestamp":"2024-02-11 18:03:05.302","source":"Logger.js:105","message":"[Database] Initializing db at \"/config/absdatabase.sqlite\"","levelName":"INFO","level":2}
{"timestamp":"2024-02-11 18:03:05.347","source":"Logger.js:105","message":"[Database] Db connection was successful","levelName":"INFO","level":2}
// NOTE: other normal healthy startup logs follow this

It does reveal that the server may be crashing and restarting itself on the scan attempt (this isn't obvious from the web view), but no crash details are given.

Note also that attempting to cancel the scan task also hangs indefinitely. The spinner with "Cancelling" state never goes away. In all cases, the spinner disappears as if no task was running if the page is hard-reloaded (Ctrl-R).

I have no issues streaming content or using the app in any other way.

Steps to reproduce the issue

In web client, click "gear" icon in top right, navigate to "Libraries" and click "Scan" on the primary Audiobook library.
Observe the task seems to start via a spinner in the toolbar, but never completes.
Observe "Socket disconnected" shortly after.

I unfortunately am not aware of the setup required to get an app in this state, but the deletion of a few library items before may or may not be relevant.

Audiobookshelf version

v2.7.2

How are you running audiobookshelf?

Docker

mikehoyle commented 9 months ago

Also noting attempted (and failed) remediation attempts:

Upgrading to latest (was reproducible on v2.7.0, still reproducible on v2.7.2).
Restarting Audiobookshelf server.

nichwall commented 9 months ago

Your server is crashing during the scan, and then docker restarts the container automatically so you see "socket disconnected" for a minute. You likely added a corrupt file or have a file that is crashing ABS (there have been some issues with some ebook files since 2.7.0).

Take a look at the docker logs to see what file is giving you issues, since the crash won't show up in the ABS logs since it can't write to the log file if it's no longer running.

mikehoyle commented 9 months ago

Ah thanks for the tip. Here's the error from the docker logs:

/node_modules/socket.io-parser/build/cjs/index.js:78
            str += JSON.stringify(obj.data, this.replacer);
                        ^

RangeError: Invalid string length
    at JSON.stringify (<anonymous>)
    at Encoder.encodeAsString (/node_modules/socket.io-parser/build/cjs/index.js:78:25)
    at Encoder.encode (/node_modules/socket.io-parser/build/cjs/index.js:54:22)
    at Client._packet (/node_modules/socket.io/dist/client.js:159:28)
    at Socket.packet (/node_modules/socket.io/dist/socket.js:279:21)
    at Socket.emit (/node_modules/socket.io/dist/socket.js:156:14)
    at SocketAuthority.emitter (/server/SocketAuthority.js:49:39)
    at LibraryScanner.scanLibrary (/server/scanner/LibraryScanner.js:207:25)
    at async LibraryScanner.scan (/server/scanner/LibraryScanner.js:82:22)
Config /config /metadata

nichwall commented 9 months ago

Glad you found that, the actual error is a bit more useful. :)

Can you change your server log level to Debug and then get the logs from the crash? That should help narrow down which file is causing the crash, either due to the file being corrupt or fixing how ABS parses that specific data.

mikehoyle commented 9 months ago

Here's the debug logs:

[2024-02-12 09:51:35.962] DEBUG: [LibraryScan] "Audiobooks": New library file found with path "/audiobooks/Terry Pratchett/Terry Pratchett - Discworld Audiobooks/Discworld 29_ Night Watch (Isis Audio Books) 128br/9-111 DW29 t111.mp3" for library item "Terry Pratchett/Terry Pratchett - Discworld Audiobooks/Discworld 29_ Night Watch (Isis Audio Books) 128br" (LibraryScan.js:131)
[2024-02-12 09:51:35.993] DEBUG: [LibraryScan] "Audiobooks": Library item "Terry Pratchett/Terry Pratchett - Discworld Audiobooks/Discworld 29_ Night Watch (Isis Audio Books) 128br" changed: [size,lastScan] (LibraryScan.js:131)
[2024-02-12 09:51:36.306] DEBUG: [ApiCacheManager] libraryItem.afterUpdate: Clearing cache (ApiCacheManager.js:21)
[2024-02-12 09:51:50.533] DEBUG: [AudioFileScanner] Smart track order for "Terry Pratchett/Terry Pratchett - Discworld Audiobooks/Discworld 29_ Night Watch (Isis Audio Books) 128br" using disc key discNumFromMeta and track key trackNumFromMeta (AudioFileScanner.js:87)
[2024-02-12 09:51:50.583] DEBUG: [LibraryScan] "Audiobooks": "Discworld 29_ Night Watch (Isis Audio Books) 128br" Getting metadata with precedence [folderStructure, audioMetatags, txtFiles, opfFile, absMetadata] (LibraryScan.js:131)
[2024-02-12 09:51:50.617] DEBUG: [LibraryScan] "Audiobooks": Found metadata file "/metadata/items/0d203fcb-f52b-418b-b599-65719a76fddf/metadata.json" (LibraryScan.js:131)
[2024-02-12 09:51:51.412] DEBUG: [ApiCacheManager] book.afterUpdate: Clearing cache (ApiCacheManager.js:21)
[2024-02-12 09:51:51.428] DEBUG: [LibraryScan] "Audiobooks": Success saving abmetadata to "/metadata/items/0d203fcb-f52b-418b-b599-65719a76fddf/metadata.json" (LibraryScan.js:131)
/node_modules/socket.io-parser/build/cjs/index.js:78
            str += JSON.stringify(obj.data, this.replacer);
                        ^

RangeError: Invalid string length
    at JSON.stringify (<anonymous>)
    at Encoder.encodeAsString (/node_modules/socket.io-parser/build/cjs/index.js:78:25)
    at Encoder.encode (/node_modules/socket.io-parser/build/cjs/index.js:54:22)
    at Client._packet (/node_modules/socket.io/dist/client.js:159:28)
    at Socket.packet (/node_modules/socket.io/dist/socket.js:279:21)
    at Socket.emit (/node_modules/socket.io/dist/socket.js:156:14)
    at SocketAuthority.emitter (/server/SocketAuthority.js:49:39)
    at LibraryScanner.scanLibrary (/server/scanner/LibraryScanner.js:207:25)
    at async LibraryScanner.scan (/server/scanner/LibraryScanner.js:82:22)
    at async ApiRouter.scan (/server/controllers/LibraryController.js:810:5)
Config /config /metadata

Not terribly insightful, but indicates the particular media item that may be causing problems. For what it's worth, it's indicating this is a "New audio file" even though I definitely haven't touched it in at least a year.

nichwall commented 9 months ago

You may be running into an inode issue similar to the linked issue, which is why it's showing up as a new item.

https://github.com/advplyr/audiobookshelf/issues/2509

mikehoyle commented 9 months ago

I must've had a corrupted library item or something along those lines.. I've resolved the situation now. For posterity, here's what I did to resolve the situation:

Turn on debug logging (Web GUI, Logs, Log Level dropdown)
Repro the crash and see what was scanning at that time.
Remove the item (in my case, the entire author), from my library files.
Manually query the sqllite table to delete all from libraryItems & books table that match the offender.
Restart and re-scan.

It was a process, but we're stable again! Thanks @nichwall for the help.

SmokeGSU commented 3 months ago

@mikehoyle just wanted to add 5 months later that your directions on getting to the debug log saved me from a bunch of headaches. I had near identical problems and had no clue what was causing my scan to crash after a few seconds of starting. I'd previously set up the library and then went to rebuild it after I was finding that certain files weren't found even after I'd successfully uploaded them. Never had any issues until now, but your instructions helped me find several metadata.json files that were causing "incompatible chapter title" issues - opening one of them, it seemed that while the metadata was indicating chapter timestamps it wasn't providing a name for the chapters. Deleting those particular .json files got me back up and running after following your instructions.

advplyr / audiobookshelf