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.

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

[Bug]: ABS Server becomes unreachable #3251

Closed
PulsarFTW opened this issue Aug 7, 2024 · 37 comments
Closed

[Bug]: ABS Server becomes unreachable #3251

PulsarFTW opened this issue Aug 7, 2024 · 37 comments
Labels
bug Something isn't working

Comments

@PulsarFTW
Copy link

PulsarFTW commented Aug 7, 2024

What happened?

This morning (07:00 local time) my audiobookshelf instance was unreachable via the app and browser. I checked using the internal IP and external address.

There are no entries in the debug log or the server crash log and I don't know what time the issue occurred.

Additional Information:
-My automatic backup scheduled at 06:00 did not run.
-I changed the time and ran an automatic backup after this incident which was successful so crash unlikely to be related.
-I upgraded to 2.12.1 yesterday and this was the first night this version was running.
-No new books/files have been added for two days.

What did you expect to happen?

I expected to be able to reach the ABS install via website/app. This is the first crash I've noticed on this install in 6+ months.

Steps to reproduce the issue

Currently unknown, sorry.

Audiobookshelf version

2.12.1

How are you running audiobookshelf?

Docker

What OS is your Audiobookshelf server hosted from?

Linux

If the issue is being seen in the UI, what browsers are you seeing the problem on?

None

Logs

{"timestamp":"2024-08-07 00:41:18.666","source":"PlaybackSessionManager.js:304","message":"[PlaybackSessionManager] syncSession \"aa20c784-8b42-4d7c-b852-a282b31b27d0\" (Device: SM-N976B SDK 31 / v0.9.74-beta) | Total Time Listened: 596","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:41:18.681","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Array.afterUpsert: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:41:18.681","source":"SocketAuthority.js:58","message":"[SocketAuthority] clientEmitter - no clients found for user edd38149-4318-4100-b8de-9434198f65bd","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:41:18.693","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Object.afterBulkUpdate: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:41:33.691","source":"PlaybackSessionManager.js:304","message":"[PlaybackSessionManager] syncSession \"aa20c784-8b42-4d7c-b852-a282b31b27d0\" (Device: SM-N976B SDK 31 / v0.9.74-beta) | Total Time Listened: 610","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:41:33.706","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Array.afterUpsert: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:41:33.707","source":"SocketAuthority.js:58","message":"[SocketAuthority] clientEmitter - no clients found for user edd38149-4318-4100-b8de-9434198f65bd","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:41:33.719","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Object.afterBulkUpdate: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:41:48.662","source":"PlaybackSessionManager.js:304","message":"[PlaybackSessionManager] syncSession \"aa20c784-8b42-4d7c-b852-a282b31b27d0\" (Device: SM-N976B SDK 31 / v0.9.74-beta) | Total Time Listened: 624","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:41:48.678","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Array.afterUpsert: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:41:48.679","source":"SocketAuthority.js:58","message":"[SocketAuthority] clientEmitter - no clients found for user edd38149-4318-4100-b8de-9434198f65bd","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:41:48.690","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Object.afterBulkUpdate: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:03.670","source":"PlaybackSessionManager.js:304","message":"[PlaybackSessionManager] syncSession \"aa20c784-8b42-4d7c-b852-a282b31b27d0\" (Device: SM-N976B SDK 31 / v0.9.74-beta) | Total Time Listened: 638","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:03.684","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Array.afterUpsert: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:03.684","source":"SocketAuthority.js:58","message":"[SocketAuthority] clientEmitter - no clients found for user edd38149-4318-4100-b8de-9434198f65bd","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:03.697","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Object.afterBulkUpdate: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:18.661","source":"PlaybackSessionManager.js:304","message":"[PlaybackSessionManager] syncSession \"aa20c784-8b42-4d7c-b852-a282b31b27d0\" (Device: SM-N976B SDK 31 / v0.9.74-beta) | Total Time Listened: 652","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:18.676","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Array.afterUpsert: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:18.677","source":"SocketAuthority.js:58","message":"[SocketAuthority] clientEmitter - no clients found for user edd38149-4318-4100-b8de-9434198f65bd","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:18.689","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Object.afterBulkUpdate: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:33.699","source":"PlaybackSessionManager.js:304","message":"[PlaybackSessionManager] syncSession \"aa20c784-8b42-4d7c-b852-a282b31b27d0\" (Device: SM-N976B SDK 31 / v0.9.74-beta) | Total Time Listened: 666","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:33.713","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Array.afterUpsert: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:33.714","source":"SocketAuthority.js:58","message":"[SocketAuthority] clientEmitter - no clients found for user edd38149-4318-4100-b8de-9434198f65bd","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:33.726","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Object.afterBulkUpdate: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:48.710","source":"PlaybackSessionManager.js:304","message":"[PlaybackSessionManager] syncSession \"aa20c784-8b42-4d7c-b852-a282b31b27d0\" (Device: SM-N976B SDK 31 / v0.9.74-beta) | Total Time Listened: 680","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:48.724","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Array.afterUpsert: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:48.725","source":"SocketAuthority.js:58","message":"[SocketAuthority] clientEmitter - no clients found for user edd38149-4318-4100-b8de-9434198f65bd","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:42:48.737","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Object.afterBulkUpdate: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:43:03.661","source":"PlaybackSessionManager.js:304","message":"[PlaybackSessionManager] syncSession \"aa20c784-8b42-4d7c-b852-a282b31b27d0\" (Device: SM-N976B SDK 31 / v0.9.74-beta) | Total Time Listened: 694","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:43:03.677","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Array.afterUpsert: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:43:03.677","source":"SocketAuthority.js:58","message":"[SocketAuthority] clientEmitter - no clients found for user edd38149-4318-4100-b8de-9434198f65bd","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:43:03.689","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Object.afterBulkUpdate: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:43:18.661","source":"PlaybackSessionManager.js:304","message":"[PlaybackSessionManager] syncSession \"aa20c784-8b42-4d7c-b852-a282b31b27d0\" (Device: SM-N976B SDK 31 / v0.9.74-beta) | Total Time Listened: 708","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:43:18.675","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Array.afterUpsert: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:43:18.676","source":"SocketAuthority.js:58","message":"[SocketAuthority] clientEmitter - no clients found for user edd38149-4318-4100-b8de-9434198f65bd","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 00:43:18.685","source":"ApiCacheManager.js:21","message":"[ApiCacheManager] Object.afterBulkUpdate: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:38.733","source":"LogManager.js:71","message":"[LogManager] Daily log file already exists - set in Logger","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:38.738","source":"DailyLog.js:132","message":"[DailyLog] 2024-08-07: Loaded 179 Logs","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:38.285","source":"Server.js:177","message":"=== Starting Server ===","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.286","source":"Server.js:107","message":"[Server] Init v2.12.1","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.286","source":"Server.js:108","message":"[Server] Node.js Version: v20.16.0","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.286","source":"Server.js:109","message":"[Server] Platform: linux","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.286","source":"Server.js:110","message":"[Server] Arch: x64","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.389","source":"BinaryManager.js:329","message":"[BinaryManager] Found valid binary ffmpeg at /ffmpeg","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.390","source":"BinaryManager.js:331","message":"[BinaryManager] Updating process.env.FFMPEG_PATH","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.479","source":"BinaryManager.js:329","message":"[BinaryManager] Found valid binary ffprobe at /ffprobe","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.479","source":"BinaryManager.js:331","message":"[BinaryManager] Updating process.env.FFPROBE_PATH","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.480","source":"BinaryManager.js:329","message":"[BinaryManager] Found valid binary unicode at /unicode.so","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.480","source":"BinaryManager.js:331","message":"[BinaryManager] Updating process.env.SQLEAN_UNICODE_PATH","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.481","source":"Database.js:182","message":"[Database] Initializing db at \"/config/absdatabase.sqlite\"","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.518","source":"Database.js:232","message":"[Database] Loading extension /unicode.so","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.519","source":"Database.js:240","message":"[Database] Successfully loaded extension /unicode.so","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.519","source":"Database.js:211","message":"[Database] Db connection was successful","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.626","source":"Database.js:172","message":"[Database] Db initialized with models: user, library, libraryFolder, book, podcast, podcastEpisode, libraryItem, mediaProgress, series, bookSeries, author, bookAuthor, collection, collectionBook, playlist, playlistMediaItem, device, playbackSession, feed, feedEpisode, setting, customMetadataProvider, mediaItemShare","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.633","source":"Logger.js:103","message":"Set Log Level to DEBUG","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:38.727","source":"LogManager.js:94","message":"Daily Log file found 2024-07-31.txt","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:38.728","source":"LogManager.js:94","message":"Daily Log file found 2024-08-01.txt","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:38.728","source":"LogManager.js:94","message":"Daily Log file found 2024-08-02.txt","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:38.728","source":"LogManager.js:94","message":"Daily Log file found 2024-08-03.txt","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:38.729","source":"LogManager.js:94","message":"Daily Log file found 2024-08-04.txt","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:38.729","source":"LogManager.js:94","message":"Daily Log file found 2024-08-05.txt","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:38.730","source":"LogManager.js:94","message":"Daily Log file found 2024-08-06.txt","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:38.730","source":"LogManager.js:94","message":"Daily Log file found 2024-08-07.txt","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:38.732","source":"LogManager.js:117","message":"[LogManager] Removed daily log: 2024-07-31.txt","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.732","source":"LogManager.js:66","message":"[LogManager] Init current daily log filename: 2024-08-07.txt","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:38.893","source":"BackupManager.js:276","message":"[BackupManager] Backup found \"2024-07-28T0600\"","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:38.984","source":"BackupManager.js:276","message":"[BackupManager] Backup found \"2024-07-29T0600\"","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:39.050","source":"BackupManager.js:276","message":"[BackupManager] Backup found \"2024-07-30T0600\"","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:39.115","source":"BackupManager.js:276","message":"[BackupManager] Backup found \"2024-07-31T0600\"","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:39.179","source":"BackupManager.js:276","message":"[BackupManager] Backup found \"2024-08-01T0600\"","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:39.243","source":"BackupManager.js:276","message":"[BackupManager] Backup found \"2024-08-02T0600\"","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:39.307","source":"BackupManager.js:276","message":"[BackupManager] Backup found \"2024-08-03T0600\"","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:39.371","source":"BackupManager.js:276","message":"[BackupManager] Backup found \"2024-08-04T0600\"","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:39.435","source":"BackupManager.js:276","message":"[BackupManager] Backup found \"2024-08-05T0600\"","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:39.509","source":"BackupManager.js:276","message":"[BackupManager] Backup found \"2024-08-06T0600\"","levelName":"DEBUG","level":1}
{"timestamp":"2024-08-07 07:35:39.510","source":"BackupManager.js:280","message":"[BackupManager] 10 Backups Found","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:39.967","source":"Server.js:137","message":"[Server] Watcher is disabled","levelName":"INFO","level":2}
{"timestamp":"2024-08-07 07:35:39.977","source":"Server.js:339","message":"Listening on port :80","levelName":"INFO","level":2}

Additional Notes

I asked on discord and another user experienced the same issue.

@PulsarFTW PulsarFTW added the bug Something isn't working label Aug 7, 2024
@nichwall
Copy link
Contributor

nichwall commented Aug 7, 2024

Was the server accessible/working after upgrading to 2.12.1 and only became inaccessible later?

@PulsarFTW
Copy link
Author

Yes the server was accessible and working for at least 8 hours after the upgrade (I skipped 2.12.0). In that time it had been used by 3 people, 1x iOS and 2x Android to listen to books, I had also accessed by the website but did not start a listening session that way.

In the logs above you can see the last event that was captured before I restarted the server at 07:35 was someone listening to an audiobook using the android app.

@ic1415
Copy link
Contributor

ic1415 commented Aug 7, 2024

I had a similar experience yesterday, no logs were generated to attribute to the service outage, however I did see a significant CPU utilization spike during that time
abs

@DirkIngo
Copy link

DirkIngo commented Aug 7, 2024

My guess is that it is related to the problem in #3241. Had the same problem after upgrading. First the db crashed with " SQLITE_CORRUPT: database disk image is malformed" or "ERROR: [Database] Failed to load extension /unicode.so" and after that the server was unreachable, because it couldnt start the container with corrupted db. Do you use docker perhaps take a look in those logs also?
Problem was solved using a backup and downgrading to v2.11.0

@nichwall
Copy link
Contributor

nichwall commented Aug 7, 2024

My guess is that it is related to the problem in #3241. Had the same problem after upgrading. First the db crashed with " SQLITE_CORRUPT: database disk image is malformed" or "ERROR: [Database] Failed to load extension /unicode.so" and after that the server was unreachable, because it couldnt start the container with corrupted db. Do you use docker perhaps take a look in those logs also?
Problem was solved using a backup and downgrading to v2.11.0

I thought that issue happened immediately upon updating and wouldn't boot at all (haven't experienced #3241). This issue shows the server becoming unresponsive after the server was working on 2.12.1 for several hours

@DirkIngo
Copy link

DirkIngo commented Aug 7, 2024

I thought that issue happened immediately upon updating and wouldn't boot at all (haven't experienced #3241). This issue shows the server becoming unresponsive after the server was working on 2.12.1 for several hours

For me v2.12.1 worked sometime and just after re-scanning a library the bug in #3241 happend (I think also it happend after batch deleting stuff). Perhaps it can be triggered otherwise also. I think docker logs of this issue would be helpful. In there should be the reason why server wont start up.

@PulsarFTW
Copy link
Author

In there should be the reason why server wont start up.

The server worked after restarting the container and I can't see any errors.

The docker logs look the same as the ones from ABS (see below) and the crash_logs file has one entry from 5 months ago.

{"log":"[2024-08-07 00:43:03.677] DEBUG: [SocketAuthority] clientEmitter - no clients found for user edd38149-4318-4100-b8de-9434198f65bd (SocketAuthority.js:58)\n","stream":"stdout","time":"2024-08-06T23:43:03.677665492Z"} {"log":"[2024-08-07 00:43:03.688] DEBUG: [ApiCacheManager] Object.afterBulkUpdate: Clearing cache (ApiCacheManager.js:21)\n","stream":"stdout","time":"2024-08-06T23:43:03.689290195Z"} {"log":"[2024-08-07 00:43:18.661] DEBUG: [PlaybackSessionManager] syncSession \"aa20c784-8b42-4d7c-b852-a282b31b27d0\" (Device: SM-N976B SDK 31 / v0.9.74-beta) | Total Time Listened: 708 (PlaybackSessionManager.js:304)\n","stream":"stdout","time":"2024-08-06T23:43:18.661828369Z"} {"log":"[2024-08-07 00:43:18.675] DEBUG: [ApiCacheManager] Array.afterUpsert: Clearing cache (ApiCacheManager.js:21)\n","stream":"stdout","time":"2024-08-06T23:43:18.67595687Z"} {"log":"[2024-08-07 00:43:18.676] DEBUG: [SocketAuthority] clientEmitter - no clients found for user edd38149-4318-4100-b8de-9434198f65bd (SocketAuthority.js:58)\n","stream":"stdout","time":"2024-08-06T23:43:18.676184151Z"} {"log":"[2024-08-07 00:43:18.685] DEBUG: [ApiCacheManager] Object.afterBulkUpdate: Clearing cache (ApiCacheManager.js:21)\n","stream":"stdout","time":"2024-08-06T23:43:18.685552709Z"} {"log":"Config /config /metadata\n","stream":"stdout","time":"2024-08-07T06:35:38.273169772Z"} {"log":"[2024-08-07 07:35:38.284] INFO: === Starting Server ===\n","stream":"stdout","time":"2024-08-07T06:35:38.285038111Z"} {"log":"[2024-08-07 07:35:38.285] INFO: [Server] Init v2.12.1\n","stream":"stdout","time":"2024-08-07T06:35:38.285983204Z"} {"log":"[2024-08-07 07:35:38.286] INFO: [Server] Node.js Version: v20.16.0\n","stream":"stdout","time":"2024-08-07T06:35:38.286206786Z"} {"log":"[2024-08-07 07:35:38.286] INFO: [Server] Platform: linux\n","stream":"stdout","time":"2024-08-07T06:35:38.286451077Z"} {"log":"[2024-08-07 07:35:38.286] INFO: [Server] Arch: x64\n","stream":"stdout","time":"2024-08-07T06:35:38.286593996Z"}

@seuffert
Copy link

seuffert commented Aug 7, 2024

i experienced the same today. the server (in docker, nginx reverse proxy) became unresponsive, no further Logs were generated. after restarting (the docker container) everything is working again and no errors regarding the DB. This started to happen after the upgrade to v2.12.1

@dstapp
Copy link

dstapp commented Aug 7, 2024

Same behavior here. ABS seems to not reachable anymore after about 24h runtime for me. Only happened after upgrading to 2.12.1. No logs or anything whatsoever. Resource usage also seems to be fine here. Restarting the container fixes it for the day unless it happens again the other day :)

@die3lust1gen2
Copy link

die3lust1gen2 commented Aug 7, 2024

Noticed the same after updating to 2.12.1. Happend two times so far after about 24h. My monitoring reported that the app timed out and the CPU load for one core went up to 100%.

CPU Load (system has 4 cores)
grafik

Outages (both roughly about the same time of day)
grafik

Nothing unusual in the logs. Last entry is a rescan followed by the restart. I changed log level to debug, but I guess I have to wait 23h to see more :D

audiobookshelf_1 | [2024-08-06 20:00:00.548] INFO: [LibraryScanner] Library scan 51ab36dc-147a-467c-bee5-06289d8ab660 completed in 0:00.0 | 0 Added | 0 Updated | 0 Missing audiobookshelf_1 | Config /config /metadata audiobookshelf_1 | [2024-08-06 21:08:37.096] INFO: === Starting Server === audiobookshelf_1 | [2024-08-06 21:08:37.099] INFO: [Server] Init v2.12.1 audiobookshelf_1 | [2024-08-06 21:08:37.100] INFO: [Server] Node.js Version: v20.16.0 audiobookshelf_1 | [2024-08-06 21:08:37.100] INFO: [Server] Platform: linux audiobookshelf_1 | [2024-08-06 21:08:37.101] INFO: [Server] Arch: x64

audiobookshelf_1 | [2024-08-07 21:00:00.964] INFO: [LibraryScanner] Library scan 4b04810c-1c30-47b1-b336-08314371773f completed in 0:00.0 | 0 Added | 0 Updated | 0 Missing audiobookshelf_1 | Config /config /metadata audiobookshelf_1 | [2024-08-07 22:29:13.024] INFO: === Starting Server === audiobookshelf_1 | [2024-08-07 22:29:13.027] INFO: [Server] Init v2.12.1 audiobookshelf_1 | [2024-08-07 22:29:13.028] INFO: [Server] Node.js Version: v20.16.0 audiobookshelf_1 | [2024-08-07 22:29:13.028] INFO: [Server] Platform: linux audiobookshelf_1 | [2024-08-07 22:29:13.029] INFO: [Server] Arch: x64

@babatonga
Copy link

babatonga commented Aug 7, 2024

I encountered a similar issue after updating to version 2.12.1 yesterday. Approximately 24 hours later, the instance became unreachable. There were no automatic or scheduled library scans, folder monitoring, or similar processes running, as all those features were deactivated. Until then, the server had been running continuously 24/7 for nearly a year, with restarts only occurring for updates.

@0o-IN10SE-o0
Copy link

0o-IN10SE-o0 commented Aug 8, 2024

Sadly same issue here. I would like to provide something to solve it but nothing shown. Server was running on previous update for some weeks without any issue. Directly after update, server became unreachable. I restarted the server and was working for around 2 hours. Then was getting unreachable during tagging a new audiobook. Restarted it, didnt work. Restarted it again and worked for around 5 hours. Then became unreachable over night. Since then I can't reach it anymore at all.

EDIT: Now I found this in log (nothing changed on the server except updating it, never crashed before in months):

2024-08-08 00:07:29.195

FATAL

[Server] Unhandled rejection: SequelizeDatabaseError: SQLITE_CORRUPT: database disk image is malformed, promise: Promise { <rejected> Error at Database.<anonymous> (C:\snapshot\audiobookshelf\node_modules\sequelize\lib\dialects\sqlite\query.js:185:27) at C:\snapshot\audiobookshelf\node_modules\sequelize\lib\dialects\sqlite\query.js:183:50 at new Promise (<anonymous>) at Query.run (C:\snapshot\audiobookshelf\node_modules\sequelize\lib\dialects\sqlite\query.js:183:12) at C:\snapshot\audiobookshelf\node_modules\sequelize\lib\sequelize.js:315:28 at async SQLiteQueryInterface.update (C:\snapshot\audiobookshelf\node_modules\sequelize\lib\dialects\abstract\query-interface.js:355:12) at async Book.save (C:\snapshot\audiobookshelf\node_modules\sequelize\lib\model.js:2490:35) at async BookScanner.rescanExistingBookLibraryItem (C:\snapshot\audiobookshelf\server\scanner\BookScanner.js) at async LibraryScanner.scanLibrary (C:\snapshot\audiobookshelf\server\scanner\LibraryScanner.js) at async LibraryScanner.scan (C:\snapshot\audiobookshelf\server\scanner\LibraryScanner.js) { name: 'SequelizeDatabaseError', parent: [Error: SQLITE_CORRUPT: database disk image is malformed] { errno: 11, code: 'SQLITE_CORRUPT', sql: 'UPDATE `books` SET `title`=$1,`titleIgnorePrefix`=$2,`subtitle`=$3,`publishedYear`=$4,`publisher`=$5,`description`=$6,`asin`=$7,`language`=$8,`narrators`=$9,`tags`=$10,`updatedAt`=$11 WHERE `id` = $12' }, original: [Error: SQLITE_CORRUPT: database disk image is malformed] { errno: 11, code: 'SQLITE_CORRUPT', sql: 'UPDATE `books` SET `title`=$1,`titleIgnorePrefix`=$2,`subtitle`=$3,`publishedYear`=$4,`publisher`=$5,`description`=$6,`asin`=$7,`language`=$8,`narrators`=$9,`tags`=$10,`updatedAt`=$11 WHERE `id` = $12' }, sql: 'UPDATE `books` SET `title`=$1,`titleIgnorePrefix`=$2,`subtitle`=$3,`publishedYear`=$4,`publisher`=$5,`description`=$6,`asin`=$7,`language`=$8,`narrators`=$9,`tags`=$10,`updatedAt`=$11 WHERE `id` = $12', parameters: {} } }

Restarted it and now works again without complain about the db.

@PulsarFTW
Copy link
Author

PulsarFTW commented Aug 8, 2024

So, exactly 24 hours after last (re)starting the server it has become unreachable. CPU usage of the container has spiked to 12.5% (so one core). I am able to run commands inside the container whilst it’s not accessible.

I ran the top command to get a list of processes using the CPU:
IMG_2524

After running kill 7 to kill the node index.js process that’s using all of the CPU, the server became reachable again and seems to work without issue.

Edit: I think this issue is unrelated to the database issues that a couple of people reported.

Update: I restarted the server at 08:00 local time. I will kill the node js process around lunchtime. And then see if the crash happens after 24h of the server running (08:00 tomorrow) or after 24h of node js running (lunchtime tomorrow) as this should help narrow down further.

@mantas3
Copy link

mantas3 commented Aug 8, 2024

Docker container. Became unreachable last night, saw there was an update, restarted (~7:50) and all was good, so ignored. Today (~8:07) it died again. Check runs every 15mins, so TOD are not exact :)
image

@pjv
Copy link

pjv commented Aug 8, 2024

I’m running with docker and experiencing the same issue daily after upgrading from 2.11.0 to 2.12.1.

Can anyone tell me if it’s safe to simply downgrade back to 2.11.0 by editing my docker-compose, specifying the version and re-creating the container? That won’t cause database issues?

@migol
Copy link

migol commented Aug 8, 2024

I can confirm 2.12.1 hanging for me at certain hour (23 local, 21 UTC) with single core at full load. Rolling back docker image to 2.11.0 solved issue. No backup or automatic library scans are scheduled for that hour.

@pjv take a backup and roll it back, it worked for me.

@TheOtherLinusNoNotThatOne
Copy link

TheOtherLinusNoNotThatOne commented Aug 8, 2024

Seeing this exact behaviour in a Debian LXC install. Every few hours ABS becomes unresponsive and one core is pegged at 100% usage. Nothing in the logs.

Restarting the ABS service fixes the issue. So my "solution" is to just set a cron job to restart the ABS service every 8 hours (time arbitrarily chosen are this stage).

@pjv
Copy link

pjv commented Aug 8, 2024

@migol Thanks - 2.11.0 running again and looks fine so far; nothing adverse in the logs.

@darthrater78
Copy link

darthrater78 commented Aug 8, 2024

Exact same issues as others here. Running in an LXC container, ABS goes unresponsive after a bit and restarting seems to fix it. Checking my stats, the cpu spikes to about 50% when this issue ocuurs. And if I look back 90 days, across all my LXCs it's the only one to exhibit this behavoir since it occured after the update.

image
image

@nichwall
Copy link
Contributor

nichwall commented Aug 8, 2024

It is only the CPU which is spiking for everyone, correct? RAM, disk, and network appear normal?

@darthrater78
Copy link

It is only the CPU which is spiking for everyone, correct? RAM, disk, and network appear normal?

It was only CPU for me.

@macr0dev
Copy link

macr0dev commented Aug 8, 2024

I have woken up the past two mornings to find my docker installation of ABS unresponsive in the same manner as everyone else here. No logs indicating a problem, a quick container restart brings it back online. No usage issues in between failures.

Been rock solid for quite some time until this last update. (2.12.1)

@PulsarFTW
Copy link
Author

It is only the CPU which is spiking for everyone, correct? RAM, disk, and network appear normal?

My RAM was around ~500mb, but I have no idea if that is a normal amount after a day of use with multiple listening sessions. It doesn't seem excessive for how often it gets used. (On a fresh restart it uses bout 50mb though).

@skyzuma
Copy link

skyzuma commented Aug 8, 2024

same here on unraid 6.12.11 with docker, updated to the latest version and unreachable ... w/o any logs ... only notification was my uptime kuma instance ... restart the container work for 1 or 2 days ...

docker stats ...
image

@kuldan5853
Copy link

I can add that this behavior also happens on the windows build of ABS 2.12.1

@rpgdev
Copy link

rpgdev commented Aug 8, 2024

Had the same crash happened on 2.12.1:
{"timestamp":"2024-08-08 13:23:54.961","source":"Server.js:171","message":"[Server] Unhandled rejection: SequelizeDatabaseError: SQLITE_CORRUPT: database disk image is malformed, promise: Promise {\n <rejected> Error\n at Database.<anonymous> (/node_modules/sequelize/lib/dialects/sqlite/query.js:185:27)\n at /node_modules/sequelize/lib/dialects/sqlite/query.js:183:50\n at new Promise (<anonymous>)\n at Query.run (/node_modules/sequelize/lib/dialects/sqlite/query.js:183:12)\n at /node_modules/sequelize/lib/sequelize.js:315:28\n at process.processTicksAndRejections (node:internal/process/task_queues:95:5)\n at async SQLiteQueryInterface.bulkUpdate (/node_modules/sequelize/lib/dialects/abstract/query-interface.js:366:12)\n at async author.update (/node_modules/sequelize/lib/model.js:2010:28)\n at async ApiRouter.match (/server/controllers/AuthorController.js:325:7) {\n name: 'SequelizeDatabaseError',\n parent: [Error: SQLITE_CORRUPT: database disk image is malformed] {\n errno: 11,\n code: 'SQLITE_CORRUPT',\n sql: 'UPDATE authorsSETid=$1,name=$2,lastFirst=$3,asin=$4,description=$5,imagePath=$6,libraryId=$7,updatedAt=$8 WHERE id= $9'\n },\n original: [Error: SQLITE_CORRUPT: database disk image is malformed] {\n errno: 11,\n code: 'SQLITE_CORRUPT',\n sql: 'UPDATEauthorsSETid=$1,name=$2,lastFirst=$3,asin=$4,description=$5,imagePath=$6,libraryId=$7,updatedAt=$8 WHERE id= $9'\n },\n sql: 'UPDATEauthorsSETid=$1,name=$2,lastFirst=$3,asin=$4,description=$5,imagePath=$6,libraryId=$7,updatedAt=$8 WHERE id = $9',\n parameters: {}\n }\n}","levelName":"FATAL","level":5}

I wonder if I have to reset audiobookshelf? Sounds like the DB is corrupted. Anyways, I just updated to 2.12.1 because I tried to access abs today and saw it crashed for no reason, when I saw there were updates available and seemed to target server crashing I installed it only to have the server crash again when I tried to "match Authors", server also hasn't picked up a new book I placed on the directory I'm watching. Strange.

@rpgdev
Copy link

rpgdev commented Aug 8, 2024

Docker container. Became unreachable last night, saw there was an update, restarted (~7:50) and all was good, so ignored. Today (~8:07) it died again. Check runs every 15mins, so TOD are not exact :) image

@mantas3 What's TOD? Me wants!

@mantas3
Copy link

mantas3 commented Aug 8, 2024

@mantas3 What's TOD? Me wants!

@rpgdev time of death 😄 monitoring - uptime kuma https://github.com/louislam/uptime-kuma

@BlwAvg
Copy link

BlwAvg commented Aug 8, 2024

My Deb PPA install also crashed. I didnt collect any data because I figured it was an isolated incident. I will keep an eye on my install and collect data if it happens again.

@macr0dev
Copy link

macr0dev commented Aug 8, 2024

Docker container. Became unreachable last night, saw there was an update, restarted (~7:50) and all was good, so ignored. Today (~8:07) it died again. Check runs every 15mins, so TOD are not exact :) image

@mantas3 What's TOD? Me wants!

Time Of Death

@rpgdev
Copy link

rpgdev commented Aug 8, 2024

ESL here, didn't know that abbreviation. Guess eventually I'll have a tod too.. not to get too existential lol. I was after uptime kuma, looks like it sends you updates to whatsapp @mantas3 ? or is that telegram?

@faush01
Copy link
Contributor

faush01 commented Aug 8, 2024

I have had this happen over the last 48 hours, about 24 hours after the server was started.
I am running on Windows from source using the following command
node prod.js --port 13378 --config C:\Tools\abs\BookData\config --metadata C:\Tools\abs\BookData\metadata --source Windows
Nothing weird in the debug logs.
node locks up and I can not ctrl-c to stop it in the cmd I an running the above command in, it is like node is locked up.

@darthrater78
Copy link

Many thanks to @advplyr for getting a fix out so quickly!

@mantas3
Copy link

mantas3 commented Aug 9, 2024

ESL here, didn't know that abbreviation. Guess eventually I'll have a tod too.. not to get too existential lol. I was after uptime kuma, looks like it sends you updates to whatsapp @mantas3 ? or is that telegram?

I use telegram, but kuma supports A LOT of notification methods
https://github.com/louislam/uptime-kuma/wiki/Notification-Methods

@advplyr
Copy link
Owner

advplyr commented Aug 9, 2024

Any issue related to a crash should not go in this thread. This is specific to the issue with MemoryStore that was hanging the server with CPU spike.

The other issue getting patched in v2.12.3 in #3241 is the sqlite corrupt crashes caused by the unicode sqlite extension.

@advplyr advplyr added the waiting Waiting for OP label Aug 9, 2024
@nikolausmoll
Copy link

My Docker container was running for 24h without issues with Version 2.12.2, but was updated by Watchtower to 2.12.3 this morning, so I cannot say if it would have crashed later.

@advplyr
Copy link
Owner

advplyr commented Aug 10, 2024

This is fixed as of v2.12.2 but everyone should be on v2.12.3 to avoid the other issue happening at the same time as this one related to the unicode sqlite extension.

Thanks everyone for helping us track it down.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working
Projects
None yet
Development

No branches or pull requests