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]: The server stops running after a few minutes of startup. #3267

Closed
shanyan-wcx opened this issue Aug 10, 2024 · 10 comments · Fixed by #3313
Closed

[Bug]: The server stops running after a few minutes of startup. #3267

shanyan-wcx opened this issue Aug 10, 2024 · 10 comments · Fixed by #3313
Labels
bug Something isn't working

Comments

@shanyan-wcx
Copy link

What happened?

The server stops running after a few minutes of startup. It doesn't always happen, but once it does, it will happen continuously

What did you expect to happen?

Server runs stably.

Steps to reproduce the issue

  1. Start server
  2. Wait for a while
  3. The server has stopped running

Audiobookshelf version

v2.12.3

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?

Edge

Logs

2024-08-10 22:05:00.140

INFO

=== Starting Server ===

2024-08-10 22:05:00.141

INFO

[Server] Init v2.12.3

2024-08-10 22:05:00.141

INFO

[Server] Node.js Version: v20.16.0

2024-08-10 22:05:00.141

INFO

[Server] Platform: linux

2024-08-10 22:05:00.142

INFO

[Server] Arch: x64

2024-08-10 22:05:00.214

INFO

[BinaryManager] Found valid binary ffmpeg at /ffmpeg

2024-08-10 22:05:00.214

INFO

[BinaryManager] Updating process.env.FFMPEG_PATH

2024-08-10 22:05:00.259

INFO

[BinaryManager] Found valid binary ffprobe at /ffprobe

2024-08-10 22:05:00.259

INFO

[BinaryManager] Updating process.env.FFPROBE_PATH

2024-08-10 22:05:00.260

INFO

[Database] Initializing db at "/config/absdatabase.sqlite"

2024-08-10 22:05:00.299

INFO

[Database] Db connection was successful

2024-08-10 22:05:00.406

INFO

[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

2024-08-10 22:05:00.438

INFO

[LogManager] Init current daily log filename: 2024-08-10.txt

2024-08-10 22:05:00.454

INFO

[BackupManager] 1 Backups Found

2024-08-10 22:05:00.472

INFO

[Watcher] Initializing watcher for "有声小说".

2024-08-10 22:05:00.473

INFO

[Watcher] Initializing watcher for "播客".

2024-08-10 22:05:00.473

INFO

[Watcher] Initializing watcher for "测试".

2024-08-10 22:05:00.481

INFO

Listening on port :13378

2024-08-10 22:05:00.546

INFO

[Watcher] "测试" Ready

2024-08-10 22:05:00.555

INFO

[Watcher] "播客" Ready

2024-08-10 22:05:00.827

INFO

[SocketAuthority] Socket Connected wjFiwbxyJVkXx5pnAAAB

2024-08-10 22:05:01.766

INFO

[Watcher] "有声小说" Ready

2024-08-10 22:05:03.139

INFO

[SocketAuthority] Socket wjFiwbxyJVkXx5pnAAAB disconnected from client "shanyan" after 2311ms (Reason: transport close)

2024-08-10 22:05:04.347

INFO

[SocketAuthority] Socket Connected 52KTfeCTkOe3hFZ7AAAD

2024-08-10 22:08:22.801

FATAL

[Server] Unhandled rejection: TypeError: Cannot use 'in' operator to search for 'readable' in null, promise: Promise { <rejected> TypeError: Cannot use 'in' operator to search for 'readable' in null at new FfmpegCommand (/server/libs/fluentFfmpeg/index.js:44:49) at FfmpegCommand (/server/libs/fluentFfmpeg/index.js:39:12) at /server/utils/ffmpegHelpers.js:81:18 at new Promise (<anonymous>) at resizeImage (/server/utils/ffmpegHelpers.js:79:10) at CacheManager.handleAuthorCache (/server/managers/CacheManager.js:154:29) }

2024-08-10 22:09:22.669

INFO

=== Starting Server ===

2024-08-10 22:09:22.670

INFO

[Server] Init v2.12.3

2024-08-10 22:09:22.670

INFO

[Server] Node.js Version: v20.16.0

2024-08-10 22:09:22.671

INFO

[Server] Platform: linux

2024-08-10 22:09:22.671

INFO

[Server] Arch: x64

2024-08-10 22:09:22.746

INFO

[BinaryManager] Found valid binary ffmpeg at /ffmpeg

2024-08-10 22:09:22.747

INFO

[BinaryManager] Updating process.env.FFMPEG_PATH

2024-08-10 22:09:22.792

INFO

[BinaryManager] Found valid binary ffprobe at /ffprobe

2024-08-10 22:09:22.792

INFO

[BinaryManager] Updating process.env.FFPROBE_PATH

2024-08-10 22:09:22.793

INFO

[Database] Initializing db at "/config/absdatabase.sqlite"

2024-08-10 22:09:22.832

INFO

[Database] Db connection was successful

2024-08-10 22:09:22.937

INFO

[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

2024-08-10 22:09:22.976

INFO

[LogManager] Init current daily log filename: 2024-08-10.txt

2024-08-10 22:09:22.991

INFO

[BackupManager] 1 Backups Found

2024-08-10 22:09:23.010

INFO

[Watcher] Initializing watcher for "有声小说".

2024-08-10 22:09:23.011

INFO

[Watcher] Initializing watcher for "播客".

2024-08-10 22:09:23.011

INFO

[Watcher] Initializing watcher for "测试".

2024-08-10 22:09:23.019

INFO

Listening on port :13378

2024-08-10 22:09:23.079

INFO

[Watcher] "测试" Ready

2024-08-10 22:09:23.086

INFO

[Watcher] "播客" Ready

2024-08-10 22:09:24.309

INFO

[Watcher] "有声小说" Ready

2024-08-10 22:09:25.119

INFO

[SocketAuthority] Socket Connected wcpGnywA6SWWXl-gAAAB

2024-08-10 22:09:27.191

INFO

[SocketAuthority] Socket wcpGnywA6SWWXl-gAAAB disconnected from client "shanyan" after 2072ms (Reason: transport close)

2024-08-10 22:09:28.392

INFO

[SocketAuthority] Socket Connected qqARu3SScq4qbwISAAAD

2024-08-10 22:13:09.407

INFO

[SocketAuthority] Socket qqARu3SScq4qbwISAAAD disconnected from client "shanyan" after 221014ms (Reason: transport close)

2024-08-10 22:19:32.159

INFO

[SocketAuthority] Socket Connected 9A3K_w80QplQZZ0MAAAF

2024-08-10 22:19:50.533

INFO

[SocketAuthority] Socket 9A3K_w80QplQZZ0MAAAF disconnected from client "shanyan" after 18374ms (Reason: transport close)

2024-08-10 22:30:09.563

INFO

[SocketAuthority] Socket Connected FgUxsjI5Y2OCi3YLAAAH

2024-08-10 22:30:20.813

INFO

[Server] Requesting rss feed 755c5682-84ba-4b07-ab52-dbc265338733

2024-08-10 22:30:20.816

WARN

[RssFeedManager] Feed not found 755c5682-84ba-4b07-ab52-dbc265338733

2024-08-10 22:31:14.807

INFO

[LibraryItem] Library item "020adc66-d99e-4f51-b6c3-c62df7d77d16" updated

2024-08-10 22:31:23.871

INFO

[LibraryItem] Library item "a3ddd59b-0ec6-4039-b986-60c9459c59bc" updated

2024-08-10 22:32:38.310

INFO

[SocketAuthority] Socket FgUxsjI5Y2OCi3YLAAAH disconnected from client "shanyan" after 148747ms (Reason: transport close)

2024-08-10 22:34:30.525

INFO

=== Starting Server ===

2024-08-10 22:34:30.526

INFO

[Server] Init v2.12.3

2024-08-10 22:34:30.526

INFO

[Server] Node.js Version: v20.16.0

2024-08-10 22:34:30.526

INFO

[Server] Platform: linux

2024-08-10 22:34:30.526

INFO

[Server] Arch: x64

2024-08-10 22:34:30.588

INFO

[BinaryManager] Found valid binary ffmpeg at /ffmpeg

2024-08-10 22:34:30.589

INFO

[BinaryManager] Updating process.env.FFMPEG_PATH

2024-08-10 22:34:30.641

INFO

[BinaryManager] Found valid binary ffprobe at /ffprobe

2024-08-10 22:34:30.641

INFO

[BinaryManager] Updating process.env.FFPROBE_PATH

2024-08-10 22:34:30.642

INFO

[Database] Initializing db at "/config/absdatabase.sqlite"

2024-08-10 22:34:30.680

INFO

[Database] Db connection was successful

2024-08-10 22:34:30.788

INFO

[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

2024-08-10 22:34:30.818

INFO

[LogManager] Init current daily log filename: 2024-08-10.txt

2024-08-10 22:34:30.832

INFO

[BackupManager] 1 Backups Found

2024-08-10 22:34:30.850

INFO

[Watcher] Initializing watcher for "有声小说".

2024-08-10 22:34:30.852

INFO

[Watcher] Initializing watcher for "播客".

2024-08-10 22:34:30.852

INFO

[Watcher] Initializing watcher for "测试".

2024-08-10 22:34:30.859

INFO

Listening on port :13378

2024-08-10 22:34:30.912

INFO

[Watcher] "测试" Ready

2024-08-10 22:34:30.917

INFO

[Watcher] "播客" Ready

2024-08-10 22:34:31.981

INFO

[Watcher] "有声小说" Ready

2024-08-10 22:49:05.400

INFO

[SocketAuthority] Socket Connected ul5v2CWPe3uhPdXnAAAB

2024-08-10 22:49:13.357

INFO

[SocketAuthority] Socket ul5v2CWPe3uhPdXnAAAB disconnected from client "shanyan" after 7958ms (Reason: transport close)

2024-08-10 22:49:41.844

FATAL

[Server] Unhandled rejection: TypeError: Cannot use 'in' operator to search for 'readable' in null, promise: Promise { <rejected> TypeError: Cannot use 'in' operator to search for 'readable' in null at new FfmpegCommand (/server/libs/fluentFfmpeg/index.js:44:49) at FfmpegCommand (/server/libs/fluentFfmpeg/index.js:39:12) at /server/utils/ffmpegHelpers.js:81:18 at new Promise (<anonymous>) at resizeImage (/server/utils/ffmpegHelpers.js:79:10) at CacheManager.handleAuthorCache (/server/managers/CacheManager.js:154:29) }

2024-08-10 22:51:00.463

INFO

=== Starting Server ===

2024-08-10 22:51:00.464

INFO

[Server] Init v2.12.3

2024-08-10 22:51:00.464

INFO

[Server] Node.js Version: v20.16.0

2024-08-10 22:51:00.464

INFO

[Server] Platform: linux

2024-08-10 22:51:00.465

INFO

[Server] Arch: x64

2024-08-10 22:51:00.534

INFO

[BinaryManager] Found valid binary ffmpeg at /ffmpeg

2024-08-10 22:51:00.535

INFO

[BinaryManager] Updating process.env.FFMPEG_PATH

2024-08-10 22:51:00.580

INFO

[BinaryManager] Found valid binary ffprobe at /ffprobe

2024-08-10 22:51:00.580

INFO

[BinaryManager] Updating process.env.FFPROBE_PATH

2024-08-10 22:51:00.581

INFO

[Database] Initializing db at "/config/absdatabase.sqlite"

2024-08-10 22:51:00.617

INFO

[Database] Db connection was successful

2024-08-10 22:51:00.720

INFO

[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

2024-08-10 22:51:00.750

INFO

[LogManager] Init current daily log filename: 2024-08-10.txt

2024-08-10 22:51:00.766

INFO

[BackupManager] 1 Backups Found

2024-08-10 22:51:00.784

INFO

[Watcher] Initializing watcher for "有声小说".

2024-08-10 22:51:00.785

INFO

[Watcher] Initializing watcher for "播客".

2024-08-10 22:51:00.786

INFO

[Watcher] Initializing watcher for "测试".

2024-08-10 22:51:00.793

INFO

Listening on port :13378

2024-08-10 22:51:00.849

INFO

[Watcher] "测试" Ready

2024-08-10 22:51:00.855

INFO

[Watcher] "播客" Ready

2024-08-10 22:51:01.891

INFO

[Watcher] "有声小说" Ready

2024-08-10 22:53:22.509

INFO

=== Starting Server ===

2024-08-10 22:53:22.510

INFO

[Server] Init v2.12.3

2024-08-10 22:53:22.510

INFO

[Server] Node.js Version: v20.16.0

2024-08-10 22:53:22.510

INFO

[Server] Platform: linux

2024-08-10 22:53:22.510

INFO

[Server] Arch: x64

2024-08-10 22:53:22.574

INFO

[BinaryManager] Found valid binary ffmpeg at /ffmpeg

2024-08-10 22:53:22.575

INFO

[BinaryManager] Updating process.env.FFMPEG_PATH

2024-08-10 22:53:22.620

INFO

[BinaryManager] Found valid binary ffprobe at /ffprobe

2024-08-10 22:53:22.620

INFO

[BinaryManager] Updating process.env.FFPROBE_PATH

2024-08-10 22:53:22.621

INFO

[Database] Initializing db at "/config/absdatabase.sqlite"

2024-08-10 22:53:22.658

INFO

[Database] Db connection was successful

2024-08-10 22:53:22.762

INFO

[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

2024-08-10 22:53:22.794

INFO

[LogManager] Init current daily log filename: 2024-08-10.txt

2024-08-10 22:53:22.809

INFO

[BackupManager] 1 Backups Found

2024-08-10 22:53:22.827

INFO

[Watcher] Initializing watcher for "有声小说".

2024-08-10 22:53:22.829

INFO

[Watcher] Initializing watcher for "播客".

2024-08-10 22:53:22.829

INFO

[Watcher] Initializing watcher for "测试".

2024-08-10 22:53:22.836

INFO

Listening on port :13378

2024-08-10 22:53:22.889

INFO

[Watcher] "测试" Ready

2024-08-10 22:53:22.896

INFO

[Watcher] "播客" Ready

2024-08-10 22:53:24.022

INFO

[Watcher] "有声小说" Ready

2024-08-10 22:54:39.383

INFO

[SocketAuthority] Socket Connected C_bWaB0KybBL4pjcAAAB

Additional Notes

No response

@shanyan-wcx shanyan-wcx added the bug Something isn't working label Aug 10, 2024
@nichwall
Copy link
Contributor

Is there anything in crash_logs.txt?

@advplyr advplyr added waiting Waiting for OP unable to reproduce Issue is not yet reproducible labels Aug 10, 2024
@shanyan-wcx
Copy link
Author

{"timestamp":"2024-08-10 21:38:53.752","source":"Server.js:170","message":"[Server] Unhandled rejection: TypeError: Cannot use 'in' operator to search for 'readable' in null, promise: Promise {\n TypeError: Cannot use 'in' operator to search for 'readable' in null\n at new FfmpegCommand (/server/libs/fluentFfmpeg/index.js:44:49)\n at FfmpegCommand (/server/libs/fluentFfmpeg/index.js:39:12)\n at /server/utils/ffmpegHelpers.js:81:18\n at new Promise ()\n at resizeImage (/server/utils/ffmpegHelpers.js:79:10)\n at CacheManager.handleAuthorCache (/server/managers/CacheManager.js:154:29)\n}","levelName":"FATAL","level":5}
{"timestamp":"2024-08-10 21:38:53.753","source":"Server.js:170","message":"[Server] Unhandled rejection: TypeError: Cannot use 'in' operator to search for 'readable' in null, promise: Promise {\n TypeError: Cannot use 'in' operator to search for 'readable' in null\n at new FfmpegCommand (/server/libs/fluentFfmpeg/index.js:44:49)\n at FfmpegCommand (/server/libs/fluentFfmpeg/index.js:39:12)\n at /server/utils/ffmpegHelpers.js:81:18\n at new Promise ()\n at resizeImage (/server/utils/ffmpegHelpers.js:79:10)\n at CacheManager.handleAuthorCache (/server/managers/CacheManager.js:154:29)\n}","levelName":"FATAL","level":5}
{"timestamp":"2024-08-10 21:48:27.974","source":"Server.js:170","message":"[Server] Unhandled rejection: TypeError: Cannot use 'in' operator to search for 'readable' in null, promise: Promise {\n TypeError: Cannot use 'in' operator to search for 'readable' in null\n at new FfmpegCommand (/server/libs/fluentFfmpeg/index.js:44:49)\n at FfmpegCommand (/server/libs/fluentFfmpeg/index.js:39:12)\n at /server/utils/ffmpegHelpers.js:81:18\n at new Promise ()\n at resizeImage (/server/utils/ffmpegHelpers.js:79:10)\n at CacheManager.handleAuthorCache (/server/managers/CacheManager.js:154:29)\n}","levelName":"FATAL","level":5}
{"timestamp":"2024-08-10 21:48:27.975","source":"Server.js:170","message":"[Server] Unhandled rejection: TypeError: Cannot use 'in' operator to search for 'readable' in null, promise: Promise {\n TypeError: Cannot use 'in' operator to search for 'readable' in null\n at new FfmpegCommand (/server/libs/fluentFfmpeg/index.js:44:49)\n at FfmpegCommand (/server/libs/fluentFfmpeg/index.js:39:12)\n at /server/utils/ffmpegHelpers.js:81:18\n at new Promise ()\n at resizeImage (/server/utils/ffmpegHelpers.js:79:10)\n at CacheManager.handleAuthorCache (/server/managers/CacheManager.js:154:29)\n}","levelName":"FATAL","level":5}
{"timestamp":"2024-08-10 22:02:51.743","source":"Server.js:170","message":"[Server] Unhandled rejection: TypeError: Cannot use 'in' operator to search for 'readable' in null, promise: Promise {\n TypeError: Cannot use 'in' operator to search for 'readable' in null\n at new FfmpegCommand (/server/libs/fluentFfmpeg/index.js:44:49)\n at FfmpegCommand (/server/libs/fluentFfmpeg/index.js:39:12)\n at /server/utils/ffmpegHelpers.js:81:18\n at new Promise ()\n at resizeImage (/server/utils/ffmpegHelpers.js:79:10)\n at CacheManager.handleAuthorCache (/server/managers/CacheManager.js:154:29)\n}","levelName":"FATAL","level":5}
{"timestamp":"2024-08-10 22:02:51.743","source":"Server.js:170","message":"[Server] Unhandled rejection: TypeError: Cannot use 'in' operator to search for 'readable' in null, promise: Promise {\n TypeError: Cannot use 'in' operator to search for 'readable' in null\n at new FfmpegCommand (/server/libs/fluentFfmpeg/index.js:44:49)\n at FfmpegCommand (/server/libs/fluentFfmpeg/index.js:39:12)\n at /server/utils/ffmpegHelpers.js:81:18\n at new Promise ()\n at resizeImage (/server/utils/ffmpegHelpers.js:79:10)\n at CacheManager.handleAuthorCache (/server/managers/CacheManager.js:154:29)\n}","levelName":"FATAL","level":5}
{"timestamp":"2024-08-10 22:08:22.801","source":"Server.js:170","message":"[Server] Unhandled rejection: TypeError: Cannot use 'in' operator to search for 'readable' in null, promise: Promise {\n TypeError: Cannot use 'in' operator to search for 'readable' in null\n at new FfmpegCommand (/server/libs/fluentFfmpeg/index.js:44:49)\n at FfmpegCommand (/server/libs/fluentFfmpeg/index.js:39:12)\n at /server/utils/ffmpegHelpers.js:81:18\n at new Promise ()\n at resizeImage (/server/utils/ffmpegHelpers.js:79:10)\n at CacheManager.handleAuthorCache (/server/managers/CacheManager.js:154:29)\n}","levelName":"FATAL","level":5}
{"timestamp":"2024-08-10 22:33:58.003","source":"Server.js:170","message":"[Server] Unhandled rejection: TypeError: Cannot use 'in' operator to search for 'readable' in null, promise: Promise {\n TypeError: Cannot use 'in' operator to search for 'readable' in null\n at new FfmpegCommand (/server/libs/fluentFfmpeg/index.js:44:49)\n at FfmpegCommand (/server/libs/fluentFfmpeg/index.js:39:12)\n at /server/utils/ffmpegHelpers.js:81:18\n at new Promise ()\n at resizeImage (/server/utils/ffmpegHelpers.js:79:10)\n at CacheManager.handleAuthorCache (/server/managers/CacheManager.js:154:29)\n}","levelName":"FATAL","level":5}
{"timestamp":"2024-08-10 22:33:58.004","source":"Server.js:170","message":"[Server] Unhandled rejection: TypeError: Cannot use 'in' operator to search for 'readable' in null, promise: Promise {\n TypeError: Cannot use 'in' operator to search for 'readable' in null\n at new FfmpegCommand (/server/libs/fluentFfmpeg/index.js:44:49)\n at FfmpegCommand (/server/libs/fluentFfmpeg/index.js:39:12)\n at /server/utils/ffmpegHelpers.js:81:18\n at new Promise ()\n at resizeImage (/server/utils/ffmpegHelpers.js:79:10)\n at CacheManager.handleAuthorCache (/server/managers/CacheManager.js:154:29)\n}","levelName":"FATAL","level":5}
{"timestamp":"2024-08-10 22:49:41.844","source":"Server.js:170","message":"[Server] Unhandled rejection: TypeError: Cannot use 'in' operator to search for 'readable' in null, promise: Promise {\n TypeError: Cannot use 'in' operator to search for 'readable' in null\n at new FfmpegCommand (/server/libs/fluentFfmpeg/index.js:44:49)\n at FfmpegCommand (/server/libs/fluentFfmpeg/index.js:39:12)\n at /server/utils/ffmpegHelpers.js:81:18\n at new Promise ()\n at resizeImage (/server/utils/ffmpegHelpers.js:79:10)\n at CacheManager.handleAuthorCache (/server/managers/CacheManager.js:154:29)\n}","levelName":"FATAL","level":5}
{"timestamp":"2024-08-10 22:52:49.426","source":"Server.js:170","message":"[Server] Unhandled rejection: TypeError: Cannot use 'in' operator to search for 'readable' in null, promise: Promise {\n TypeError: Cannot use 'in' operator to search for 'readable' in null\n at new FfmpegCommand (/server/libs/fluentFfmpeg/index.js:44:49)\n at FfmpegCommand (/server/libs/fluentFfmpeg/index.js:39:12)\n at /server/utils/ffmpegHelpers.js:81:18\n at new Promise ()\n at resizeImage (/server/utils/ffmpegHelpers.js:79:10)\n at CacheManager.handleAuthorCache (/server/managers/CacheManager.js:154:29)\n}","levelName":"FATAL","level":5}
{"timestamp":"2024-08-10 22:52:49.427","source":"Server.js:170","message":"[Server] Unhandled rejection: TypeError: Cannot use 'in' operator to search for 'readable' in null, promise: Promise {\n TypeError: Cannot use 'in' operator to search for 'readable' in null\n at new FfmpegCommand (/server/libs/fluentFfmpeg/index.js:44:49)\n at FfmpegCommand (/server/libs/fluentFfmpeg/index.js:39:12)\n at /server/utils/ffmpegHelpers.js:81:18\n at new Promise ()\n at resizeImage (/server/utils/ffmpegHelpers.js:79:10)\n at CacheManager.handleAuthorCache (/server/managers/CacheManager.js:154:29)\n}","levelName":"FATAL","level":5}
{"timestamp":"2024-08-11 09:24:25.216","source":"Server.js:170","message":"[Server] Unhandled rejection: TypeError: Cannot use 'in' operator to search for 'readable' in null, promise: Promise {\n TypeError: Cannot use 'in' operator to search for 'readable' in null\n at new FfmpegCommand (/server/libs/fluentFfmpeg/index.js:44:49)\n at FfmpegCommand (/server/libs/fluentFfmpeg/index.js:39:12)\n at /server/utils/ffmpegHelpers.js:81:18\n at new Promise ()\n at resizeImage (/server/utils/ffmpegHelpers.js:79:10)\n at CacheManager.handleAuthorCache (/server/managers/CacheManager.js:154:29)\n}","levelName":"FATAL","level":5}

@shanyan-wcx
Copy link
Author

After my testing, I found that when I call the Get an Author's Image API, if there is no image, it will cause the server to crash.

@shanyan-wcx
Copy link
Author

If there is no image, it will not return a 404

@hoggatt
Copy link

hoggatt commented Aug 12, 2024

I'm experiencing the same behavior, somewhat intermittently

@CraigMThomas
Copy link

CraigMThomas commented Aug 12, 2024

I seem to be getting something similar. After updating from v2.11.0 to v2.12.3 and trying to run a library scan, the page will appear to freeze, and I can observe the following logs over and over. Downgrading to v2.11.0 again does not resolve this issue.

Aug 13 01:29:40 systemd[1]: Started Self-hosted audiobook server for managing and playing audiobooks.
Aug 13 01:29:40 audiobookshelf[2299]: production Config /var/lib/audiobookshelf/config /var/lib/audiobookshelf/metadata
Aug 13 01:29:40 audiobookshelf[2299]: [2024-08-13 01:29:40.968] INFO: === Starting Server ===
Aug 13 01:29:40 audiobookshelf[2299]: [2024-08-13 01:29:40.969] INFO: [Server] Init v2.12.3
Aug 13 01:29:40 audiobookshelf[2299]: [2024-08-13 01:29:40.970] INFO: [Server] Node.js Version: v20.11.1
Aug 13 01:29:40 audiobookshelf[2299]: [2024-08-13 01:29:40.970] INFO: [Server] Platform: linux
Aug 13 01:29:40 audiobookshelf[2299]: [2024-08-13 01:29:40.970] INFO: [Server] Arch: x64
Aug 13 01:29:40 audiobookshelf[2299]: [2024-08-13 01:29:40.979] INFO: [BinaryManager] Found valid binary ffmpeg at ffmpeg
Aug 13 01:29:40 audiobookshelf[2299]: [2024-08-13 01:29:40.979] INFO: [BinaryManager] Updating process.env.FFMPEG_PATH
Aug 13 01:29:40 audiobookshelf[2299]: [2024-08-13 01:29:40.982] INFO: [BinaryManager] Found valid binary ffprobe at ffprobe
Aug 13 01:29:40 audiobookshelf[2299]: [2024-08-13 01:29:40.983] INFO: [BinaryManager] Updating process.env.FFPROBE_PATH
Aug 13 01:29:40 audiobookshelf[2299]: [2024-08-13 01:29:40.983] INFO: [Database] Initializing db at "/var/lib/audiobookshelf/config/absdatabase.sqlite"
Aug 13 01:29:41 audiobookshelf[2299]: [2024-08-13 01:29:41.028] INFO: [Database] Db connection was successful
Aug 13 01:29:41 audiobookshelf[2299]: [2024-08-13 01:29:41.118] INFO: [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
Aug 13 01:29:41 audiobookshelf[2299]: [2024-08-13 01:29:41.139] INFO: [LogManager] Init current daily log filename: 2024-08-13.txt
Aug 13 01:29:41 audiobookshelf[2299]: [2024-08-13 01:29:41.177] INFO: [BackupManager] 0 Backups Found
Aug 13 01:29:41 audiobookshelf[2299]: [2024-08-13 01:29:41.180] INFO: [BackupManager] Auto Backups are disabled
Aug 13 01:29:41 audiobookshelf[2299]: [2024-08-13 01:29:41.190] INFO: [Watcher] Initializing watcher for "AudioBooks".
Aug 13 01:29:41 audiobookshelf[2299]: Warning: connect.session() MemoryStore is not
Aug 13 01:29:41 audiobookshelf[2299]: designed for a production environment, as it will leak
Aug 13 01:29:41 audiobookshelf[2299]: memory, and will not scale past a single process.
Aug 13 01:29:41 audiobookshelf[2299]: [2024-08-13 01:29:41.197] INFO: Listening on http://0.0.0.0:13378
Aug 13 01:29:41 audiobookshelf[2299]: [2024-08-13 01:29:41.409] INFO: [SocketAuthority] Socket Connected L3EhTp1NqRVsQvluAAAB
Aug 13 01:29:51 audiobookshelf[2299]: [2024-08-13 01:29:51.648] FATAL: [Server] Uncaught exception origin: uncaughtException, error: Error: spawn EPERM
Aug 13 01:29:51 audiobookshelf[2299]:     at ChildProcess.spawn (node:internal/child_process:421:11)
Aug 13 01:29:51 audiobookshelf[2299]:     at spawn (node:child_process:761:9)
Aug 13 01:29:51 audiobookshelf[2299]:     at /usr/share/audiobookshelf/server/libs/fluentFfmpeg/processor.js:148:24
Aug 13 01:29:51 audiobookshelf[2299]:     at /usr/share/audiobookshelf/server/libs/fluentFfmpeg/capabilities.js:123:9
Aug 13 01:29:51 audiobookshelf[2299]:     at t (/usr/share/audiobookshelf/server/libs/async/index.js:6:1639)
Aug 13 01:29:51 audiobookshelf[2299]:     at a (/usr/share/audiobookshelf/server/libs/async/index.js:6:18659)
Aug 13 01:29:51 audiobookshelf[2299]:     at /usr/share/audiobookshelf/server/libs/async/index.js:6:2258
Aug 13 01:29:51 audiobookshelf[2299]:     at /usr/share/audiobookshelf/server/libs/fluentFfmpeg/capabilities.js:112:18
Aug 13 01:29:51 audiobookshelf[2299]:     at n (/usr/share/audiobookshelf/server/libs/async/index.js:6:18591)
Aug 13 01:29:51 audiobookshelf[2299]:     at a (/usr/share/audiobookshelf/server/libs/async/index.js:6:18674) {
Aug 13 01:29:51 audiobookshelf[2299]:   errno: -1,
Aug 13 01:29:51 audiobookshelf[2299]:   code: 'EPERM',
Aug 13 01:29:51 audiobookshelf[2299]:   syscall: 'spawn'
Aug 13 01:29:51 audiobookshelf[2299]: } (Server.js:164)
Aug 13 01:29:51 audiobookshelf[2299]: node:internal/child_process:421
Aug 13 01:29:51 audiobookshelf[2299]:     throw errnoException(err, 'spawn');
Aug 13 01:29:51 audiobookshelf[2299]:     ^
Aug 13 01:29:51 audiobookshelf[2299]: Error: spawn EPERM
Aug 13 01:29:51 audiobookshelf[2299]:     at ChildProcess.spawn (node:internal/child_process:421:11)
Aug 13 01:29:51 audiobookshelf[2299]:     at spawn (node:child_process:761:9)
Aug 13 01:29:51 audiobookshelf[2299]:     at /usr/share/audiobookshelf/server/libs/fluentFfmpeg/processor.js:148:24
Aug 13 01:29:51 audiobookshelf[2299]:     at /usr/share/audiobookshelf/server/libs/fluentFfmpeg/capabilities.js:123:9
Aug 13 01:29:51 audiobookshelf[2299]:     at t (/usr/share/audiobookshelf/server/libs/async/index.js:6:1639)
Aug 13 01:29:51 audiobookshelf[2299]:     at a (/usr/share/audiobookshelf/server/libs/async/index.js:6:18659)
Aug 13 01:29:51 audiobookshelf[2299]:     at /usr/share/audiobookshelf/server/libs/async/index.js:6:2258
Aug 13 01:29:51 audiobookshelf[2299]:     at /usr/share/audiobookshelf/server/libs/fluentFfmpeg/capabilities.js:112:18
Aug 13 01:29:51 audiobookshelf[2299]:     at n (/usr/share/audiobookshelf/server/libs/async/index.js:6:18591)
Aug 13 01:29:51 audiobookshelf[2299]:     at a (/usr/share/audiobookshelf/server/libs/async/index.js:6:18674) {
Aug 13 01:29:51 audiobookshelf[2299]:   errno: -1,
Aug 13 01:29:51 audiobookshelf[2299]:   code: 'EPERM',
Aug 13 01:29:51 audiobookshelf[2299]:   syscall: 'spawn'
Aug 13 01:29:51 audiobookshelf[2299]: }
Aug 13 01:29:51 audiobookshelf[2299]: Node.js v20.11.1
Aug 13 01:29:51 systemd[1]: audiobookshelf.service: Main process exited, code=exited, status=1/FAILURE
Aug 13 01:29:51 systemd[1]: audiobookshelf.service: Failed with result 'exit-code'.
Aug 13 01:29:51 systemd[1]: audiobookshelf.service: Consumed 1.556s CPU time.
Aug 13 01:29:51 systemd[1]: audiobookshelf.service: Scheduled restart job, restart counter is at 20.
Aug 13 01:29:51 systemd[1]: Stopped Self-hosted audiobook server for managing and playing audiobooks.
Aug 13 01:29:51 systemd[1]: audiobookshelf.service: Consumed 1.556s CPU time.
Aug 13 01:29:51 systemd[1]: Started Self-hosted audiobook server for managing and playing audiobooks.

The restart loop occurs when I connect a new client or switch between library and home a few times.

@CraigMThomas
Copy link

If I get to the libraries configuration page and try to scan this shows for any new items

Aug 13 01:44:34 audiobookshelf[1487]: [2024-08-13 01:44:34.397] INFO: [LibraryScanner] Starting library scan 42311323-1b7e-4e67-89f5-d69540f7b47a for AudioBooks
Aug 13 01:45:07 audiobookshelf[1487]: [2024-08-13 01:45:07.439] ERROR: [AudioFileScanner] Error: spawn EPERM : "/lib/path1/book.m4b" (AudioFileScanner.js:159)
Aug 13 01:45:07 audiobookshelf[1487]: [2024-08-13 01:45:07.443] ERROR: [AudioFileScanner] Error: spawn EPERM : "/lib/path2/book.m4b" (AudioFileScanner.js:159)
Aug 13 01:45:07 audiobookshelf[1487]: [2024-08-13 01:45:07.445] ERROR: [AudioFileScanner] Error: spawn EPERM : "/lib/path3/book.m4b" (AudioFileScanner.js:159)
Aug 13 01:45:07 audiobookshelf[1487]: [2024-08-13 01:45:07.446] ERROR: [AudioFileScanner] Error: spawn EPERM : "/lib/path4/book.m4b" (AudioFileScanner.js:159)
Aug 13 01:45:07 audiobookshelf[1487]: [2024-08-13 01:45:07.446] INFO: [LibraryScanner] Library scan 42311323-1b7e-4e67-89f5-d69540f7b47a completed in 0:33.0 | 0 Added | 0 Updated | 0 Missing
Aug 13 01:45:07 audiobookshelf[1487]: [2024-08-13 01:45:07.462] INFO: [LibraryController] Scan complete

Instead of Scan I have now selected Match files. which appears to be cycling through all existing books in the library and downloading images. I'll leave that to run while I sleep and see if it clears anything up, but not holding my breath.

@Khameleon05
Copy link

Khameleon05 commented Aug 17, 2024

I'm getting the same issue, I've recently moved a server off my NAS onto Windows and restored a backup, for whatever reason most of the Author pictures appear as broken images (even though the image files are there). I was going through trashing the broken image, refreshing, and reloading the images fine, but I got to a random one halfway down and on the refresh I got the exact same error as indicated above.

I reproduced it three times in a row scanning the same author (Harlan Ellison if it matters). same error, same full crash. Interestingly it's (so far) only on that one specific author not the other 100+.

@mikiher
Copy link
Contributor

mikiher commented Aug 20, 2024

There's maybe a dipper issue here, but the crash is easy to reproduce.

  • pick an author with no image
  • construct a URL for that author's image ( /api/authors/{authorid}/image?token={token} )
  • request that URL

Our web interface actually checks if the author has an image when creating the <img> tag (in AuthorImage.vue):

    imgSrc() {
      if (!this.imagePath) return null
      if (process.env.NODE_ENV !== 'production') {
        // Testing
        return `http://localhost:3333${this.$config.routerBasePath}/api/authors/${this.authorId}/image?token=${this.userToken}&ts=${this.updatedAt}`
      }
      return `/api/authors/${this.authorId}/image?token=${this.userToken}&ts=${this.updatedAt}`
    }

This is why it's not easy to reproduce using the web interface. However the problem does seem to occur in some circumstances, and indicates that sometimes (for reasons I still need to understand better) there's some data mismatch between client and the server.

We need to fix this since the API can (in theory) be called in isolation.

The root cause for the crash is that we don't check that author.imagePath is not null (or that it exists) before we send it to FFMpeg for resizing. I'll send on a fix for that, and I'll also try to understand the data mismatch issues reported above.

@advplyr advplyr added awaiting release Issue is resolved and will be in the next release and removed waiting Waiting for OP unable to reproduce Issue is not yet reproducible labels Aug 31, 2024
Copy link

Fixed in v2.13.0.

@github-actions github-actions bot removed the awaiting release Issue is resolved and will be in the next release label Aug 31, 2024
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

Successfully merging a pull request may close this issue.

7 participants