search

advplyr / audiobookshelf

Self-hosted audiobook and podcast server
https://audiobookshelf.org
GNU General Public License v3.0
6.23k stars 436 forks source link

[Bug]: OOM Crash when loading podcast library with lots of tracks #2075

Closed paxchristos closed 8 months ago

paxchristos commented 1 year ago

Describe the issue

Upgraded to 2.4.1 from 2.3.3, was able to scan podcast library (haven't been able to do so since 2.3.x, thank you for the fix!)

Selected Podcast library, then went to library and the server starts crashing. If you leave open the webpage for the library, it'll enter a loop of starting the same process and crashing the server until the page is closed.

Podcast Library stats: 21 library items 10799 tracks

Machine Stats: ubuntu 22.04.03 i3 10100 16gb ram 256gb m2 nvme

Here's the exact OOM crash: 

<--- Last few GCs --->
[125231:0x40d4960]   200561 ms: Scavenge (reduce) 2033.5 (2053.7) -> 2033.4 (2053.7) MB, 0.6 / 0.0 ms  (average mu = 0.996, current mu = 0.925) allocation failure
[125231:0x40d4960]   200594 ms: Mark-sweep (reduce) 2036.9 (2057.1) -> 2036.8 (2056.4) MB, 28.3 / 0.1 ms  (+ 36.5 ms in 7 steps since start of marking, biggest step 36.5 ms, walltime since start of marking 94 ms) (average mu = 0.990, current mu = 0.531) a
<--- JS stacktrace --->
FATAL ERROR: Reached heap limit Allocation failed - JavaScript heap out of memory
1: 0x99e640 node::Abort() [/usr/share/audiobookshelf/audiobookshelf]
2: 0x8c9623 node::FatalError(char const*, char const*) [/usr/share/audiobookshelf/audiobookshelf]
3: 0x106a01e v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) 
4: 0x106a2c6 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/usr/share/audiobookshelf/audiobookshelf]
5: 0x122a445  [/usr/share/audiobookshelf/audiobookshelf]
6: 0x1239fa1 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/usr/share/audiobookshelf/audiobookshelf]
7: 0x123d01b v8::internal::Heap::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/usr/share/audiobookshelf/audiobookshelf]
8: 0x11f9c95 v8::internal::Factory::AllocateRaw(int, v8::internal::AllocationType, v8::internal::AllocationAlignment) [/usr/share/audiobookshelf/audiobookshelf]
9: 0x11f2404 v8::internal::FactoryBase<v8::internal::Factory>::AllocateRawWithImmortalMap(int, v8::internal::AllocationType, v8::internal::Map, v8::internal::AllocationAlignment) [/usr/share/audiobookshelf/audiobookshelf]
10: 0x11f44c0 v8::internal::FactoryBase<v8::internal::Factory>::NewRawTwoByteString(int, v8::internal::AllocationType) [/usr/share/audiobookshelf/audiobookshelf]
11: 0x11fc13b v8::internal::Factory::NewStringFromUtf8(v8::base::Vector<char const> const&, v8::internal::AllocationType) [/usr/share/audiobookshelf/audiobookshelf]
12: 0x107a97d v8::String::NewFromUtf8(v8::Isolate*, char const*, v8::NewStringType, int) [/usr/share/audiobookshelf/audiobookshelf]
13: 0x95533d napi_create_string_utf8 [/usr/share/audiobookshelf/audiobookshelf]
14: 0x7f42772cd1c7 node_sqlite3::Statement::RowToJS(Napi::Env, std::vector<node_sqlite3::Values::Field*, std::allocator<node_sqlite3::Values::Field*> >*) [/tmp/pkg/1f8cc72dfb50f0c54b04dd7a709ef5ef89b2b1f3b063270646bd12c81173b2e8/sqlite3/lib/binding/napi-v6-linux-glibc-x64/node_sqlite3.node]
15: 0x7f42772cfc1c node_sqlite3::Statement::Work_AfterAll(napi_env__*, napi_status, void*) [/tmp/pkg/1f8cc72dfb50f0c54b04dd7a709ef5ef89b2b1f3b063270646bd12c81173b2e8/sqlite3/lib/binding/napi-v6-linux-glibc-x64/node_sqlite3.node]
16: 0x974b7a  [/usr/share/audiobookshelf/audiobookshelf]
17: 0xafe4fd  [/usr/share/audiobookshelf/audiobookshelf]
18: 0xb0dca5  [/usr/share/audiobookshelf/audiobookshelf]
19: 0xb225fe  [/usr/share/audiobookshelf/audiobookshelf]
20: 0x1044828  [/usr/share/audiobookshelf/audiobookshelf]
21: 0x8fa323 node::SpinEventLoop(node::Environment*) [/usr/share/audiobookshelf/audiobookshelf]
22: 0x9e1904 node::NodeMainInstance::Run(node::EnvSerializeInfo const*) [/usr/share/audiobookshelf/audiobookshelf]
23: 0x96a36d node::Start(int, char**) [/usr/share/audiobookshelf/audiobookshelf]
24: 0x7f4286069d90  [/lib/x86_64-linux-gnu/libc.so.6]
25: 0x7f4286069e40 __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
26: 0x8ebd7c  [/usr/share/audiobookshelf/audiobookshelf]

Here's a larger section of the log: 

Sep 10 12:41:57 quickplex audiobookshelf[126767]: [2023-09-10 12:41:57] DEBUG: Loaded 10 of 32 items for "Continue Listening/Reading" in 0.21s (    at Function.getPersonalizedShelves (/snapshot/audiobookshelf/server/models/LibraryItem.js))
Sep 10 12:41:57 quickplex audiobookshelf[126767]: [2023-09-10 12:41:57] DEBUG: Loaded 0 of 0 items for "Continue Series" in 0.03s (    at Function.getPersonalizedShelves (/snapshot/audiobookshelf/server/models/LibraryItem.js))
Sep 10 12:41:57 quickplex audiobookshelf[126767]: [2023-09-10 12:41:57] DEBUG: Loaded 10 of 325 items for "Recently Added" in 0.04s (    at Function.getPersonalizedShelves (/snapshot/audiobookshelf/server/models/LibraryItem.js))
Sep 10 12:41:57 quickplex audiobookshelf[126767]: [2023-09-10 12:41:57] DEBUG: Loaded 5 of 16 series for "Recent Series" in 0.01s (    at Function.getPersonalizedShelves (/snapshot/audiobookshelf/server/models/LibraryItem.js))
Sep 10 12:41:57 quickplex audiobookshelf[126767]: [2023-09-10 12:41:57] DEBUG: Loaded 10 of 1428 items for "Discover" in 0.07s (    at Function.getPersonalizedShelves (/snapshot/audiobookshelf/server/models/LibraryItem.js))
Sep 10 12:41:57 quickplex audiobookshelf[126767]: [2023-09-10 12:41:57] DEBUG: Loaded 10 of 49 items for "Listen/Read Again" in 0.03s (    at Function.getPersonalizedShelves (/snapshot/audiobookshelf/server/models/LibraryItem.js))
Sep 10 12:41:57 quickplex audiobookshelf[126767]: [2023-09-10 12:41:57] DEBUG: Loaded 10 of 161 authors for "Newest Authors" in 0.08s (    at Function.getPersonalizedShelves (/snapshot/audiobookshelf/server/models/LibraryItem.js))
Sep 10 12:41:57 quickplex audiobookshelf[126767]: [2023-09-10 12:41:57] DEBUG: Loaded 6 personalized shelves in 0.48s (    at Function.getPersonalizedShelves (/snapshot/audiobookshelf/server/models/LibraryItem.js))
Sep 10 12:41:58 quickplex audiobookshelf[126767]: [2023-09-10 12:41:58] DEBUG: [FfmpegHelpers] Resize Image Cmd: ffmpeg -i /usr/share/audiobookshelf/metadata/items/li_be95yjucc749r6gkhy/cover.jpg -y -vf scale=400:-1 /usr/share/audiobookshelf/metadata/cache/covers/761c8c28-9072-404b-81bd-5545fe8872cd_400.webp (    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/utils/ffmpegHelpers.js))
Sep 10 12:41:59 quickplex audiobookshelf[126767]: [2023-09-10 12:41:59] DEBUG: [FfmpegHelpers] Image resized Successfully (    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/utils/ffmpegHelpers.js))
Sep 10 12:42:01 quickplex audiobookshelf[126767]: [2023-09-10 12:42:01] DEBUG: [SocketAuthority] User Offline nielson.annie33@gmail.com (    at Socket.<anonymous> (/snapshot/audiobookshelf/server/SocketAuthority.js))
Sep 10 12:42:01 quickplex audiobookshelf[126767]: [2023-09-10 12:42:01] INFO: [SocketAuthority] Socket i2XqcDbkJCxAOBQtAAAB disconnected from client "nielson.annie33@gmail.com" after 96719ms (Reason: ping timeout)
Sep 10 12:42:01 quickplex audiobookshelf[126767]: [2023-09-10 12:42:01] DEBUG: [FfmpegHelpers] Resize Image Cmd: ffmpeg -i /usr/share/audiobookshelf/metadata/items/li_3ufwk2l1ow033ered0/cover.jpg -y -vf scale=400:-1 /usr/share/audiobookshelf/metadata/cache/covers/a6de19f9-5f33-4645-ba94-692b7975b167_400.webp (    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/utils/ffmpegHelpers.js))
Sep 10 12:42:01 quickplex audiobookshelf[126767]: [2023-09-10 12:42:01] DEBUG: [FfmpegHelpers] Image resized Successfully (    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/utils/ffmpegHelpers.js))
Sep 10 12:42:03 quickplex audiobookshelf[126767]: [2023-09-10 12:42:03] DEBUG: [FfmpegHelpers] Resize Image Cmd: ffmpeg -i /usr/share/audiobookshelf/metadata/items/li_uqlzo072wi0njg1iqy/cover.jpg -y -vf scale=400:-1 /usr/share/audiobookshelf/metadata/cache/covers/463f0aa1-90de-49ac-8d08-df88ab7e602f_400.webp (    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/utils/ffmpegHelpers.js))
Sep 10 12:42:03 quickplex audiobookshelf[126767]: [2023-09-10 12:42:03] DEBUG: [FfmpegHelpers] Resize Image Cmd: ffmpeg -i /usr/share/audiobookshelf/metadata/items/li_wkjrsp7bmnkco2crvb/cover.jpg -y -vf scale=400:-1 /usr/share/audiobookshelf/metadata/cache/covers/230fda52-cb95-4572-8151-4f1fd23a6947_400.webp (    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/utils/ffmpegHelpers.js))
Sep 10 12:42:03 quickplex audiobookshelf[126767]: [2023-09-10 12:42:03] DEBUG: [FfmpegHelpers] Image resized Successfully (    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/utils/ffmpegHelpers.js))
Sep 10 12:42:03 quickplex audiobookshelf[126767]: [2023-09-10 12:42:03] DEBUG: [FfmpegHelpers] Image resized Successfully (    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/utils/ffmpegHelpers.js))
Sep 10 12:42:04 quickplex audiobookshelf[126767]: [2023-09-10 12:42:04] DEBUG: [FfmpegHelpers] Resize Image Cmd: ffmpeg -i /usr/share/audiobookshelf/metadata/items/li_wv7yemg2bl3kmr3jy1/cover.jpg -y -vf scale=400:-1 /usr/share/audiobookshelf/metadata/cache/covers/c5c4c760-5771-4ba5-b2ce-583d5f06315c_400.webp (    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/utils/ffmpegHelpers.js))
Sep 10 12:42:04 quickplex audiobookshelf[126767]: [2023-09-10 12:42:04] DEBUG: [FfmpegHelpers] Resize Image Cmd: ffmpeg -i /usr/share/audiobookshelf/metadata/items/6053651b-560b-4c5d-9bc3-f3b066c7c837/cover.jpg -y -vf scale=400:-1 /usr/share/audiobookshelf/metadata/cache/covers/6053651b-560b-4c5d-9bc3-f3b066c7c837_400.webp (    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/utils/ffmpegHelpers.js))
Sep 10 12:42:04 quickplex audiobookshelf[126767]: [2023-09-10 12:42:04] DEBUG: [FfmpegHelpers] Image resized Successfully (    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/utils/ffmpegHelpers.js))
Sep 10 12:42:04 quickplex audiobookshelf[126767]: [2023-09-10 12:42:04] DEBUG: [FfmpegHelpers] Image resized Successfully (    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/utils/ffmpegHelpers.js))
Sep 10 12:42:04 quickplex audiobookshelf[126767]: [2023-09-10 12:42:04] DEBUG: Loaded filterdata in 0.00s (    at Object.getFilterData (/snapshot/audiobookshelf/server/utils/queries/libraryFilters.js))
Sep 10 12:42:05 quickplex audiobookshelf[126767]: [2023-09-10 12:42:05] DEBUG: Loaded 2 of 2 items for "Continue Listening/Reading" in 0.04s (    at Function.getPersonalizedShelves (/snapshot/audiobookshelf/server/models/LibraryItem.js))
Sep 10 12:42:05 quickplex audiobookshelf[126767]: [2023-09-10 12:42:05] DEBUG: Loaded 10 of 291 episodes for "Newest Episodes" in 0.08s (    at Function.getPersonalizedShelves (/snapshot/audiobookshelf/server/models/LibraryItem.js))
Sep 10 12:42:05 quickplex audiobookshelf[126767]: [2023-09-10 12:42:05] DEBUG: Loaded 7 of 7 items for "Recently Added" in 0.08s (    at Function.getPersonalizedShelves (/snapshot/audiobookshelf/server/models/LibraryItem.js))
Sep 10 12:42:05 quickplex audiobookshelf[126767]: [2023-09-10 12:42:05] DEBUG: Loaded 1 of 1 items for "Listen/Read Again" in 0.01s (    at Function.getPersonalizedShelves (/snapshot/audiobookshelf/server/models/LibraryItem.js))
Sep 10 12:42:05 quickplex audiobookshelf[126767]: [2023-09-10 12:42:05] DEBUG: Loaded 4 personalized shelves in 0.20s (    at Function.getPersonalizedShelves (/snapshot/audiobookshelf/server/models/LibraryItem.js))
Sep 10 12:42:09 quickplex audiobookshelf[126767]: [2023-09-10 12:42:09] DEBUG: Loaded 28 of 28 items for libary page in 0.40s (    at Function.getByFilterAndSort (/snapshot/audiobookshelf/server/models/LibraryItem.js))
Sep 10 12:43:12 quickplex audiobookshelf[126767]: <--- Last few GCs --->
Sep 10 12:43:12 quickplex audiobookshelf[126767]: [126767:0x3cfc960]   174217 ms: Mark-sweep (reduce) 2039.6 (2051.1) -> 2039.5 (2051.4) MB, 5.0 / 0.1 ms  (+ 32.3 ms in 7 steps since start of marking, biggest step 32.3 ms, walltime since start of marking 64 ms) (average mu = 0.990, current mu = 0.629) al[126767:0x3cfc960]   174283 ms: Mark-sweep (reduce) 2043.0 (2054.8) -> 2043.0 (2054.6) MB, 61.9 / 0.1 ms  (average mu = 0.963, current mu = 0.062) allocation failure scavenge might not succeed
Sep 10 12:43:12 quickplex audiobookshelf[126767]: <--- JS stacktrace --->
Sep 10 12:43:12 quickplex audiobookshelf[126767]: FATAL ERROR: Reached heap limit Allocation failed - JavaScript heap out of memory
Sep 10 12:43:12 quickplex audiobookshelf[126767]:  1: 0x99e640 node::Abort() [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]:  2: 0x8c9623 node::FatalError(char const*, char const*) [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]:  3: 0x106a01e v8::Utils::ReportOOMFailure(v8::internal::Isolate*, char const*, bool) [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]:  4: 0x106a2c6 v8::internal::V8::FatalProcessOutOfMemory(v8::internal::Isolate*, char const*, bool) [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]:  5: 0x122a445  [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]:  6: 0x1239fa1 v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, v8::internal::GarbageCollectionReason, v8::GCCallbackFlags) [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]:  7: 0x123d01b v8::internal::Heap::AllocateRawWithRetryOrFailSlowPath(int, v8::internal::AllocationType, v8::internal::AllocationOrigin, v8::internal::AllocationAlignment) [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]:  8: 0x11f9c95 v8::internal::Factory::AllocateRaw(int, v8::internal::AllocationType, v8::internal::AllocationAlignment) [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]:  9: 0x11f2404 v8::internal::FactoryBase<v8::internal::Factory>::AllocateRawWithImmortalMap(int, v8::internal::AllocationType, v8::internal::Map, v8::internal::AllocationAlignment) [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 10: 0x11f44c0 v8::internal::FactoryBase<v8::internal::Factory>::NewRawTwoByteString(int, v8::internal::AllocationType) [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 11: 0x11fc13b v8::internal::Factory::NewStringFromUtf8(v8::base::Vector<char const> const&, v8::internal::AllocationType) [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 12: 0x107a97d v8::String::NewFromUtf8(v8::Isolate*, char const*, v8::NewStringType, int) [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 13: 0x95533d napi_create_string_utf8 [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 14: 0x7fb2a808e1c7 node_sqlite3::Statement::RowToJS(Napi::Env, std::vector<node_sqlite3::Values::Field*, std::allocator<node_sqlite3::Values::Field*> >*) [/tmp/pkg/1f8cc72dfb50f0c54b04dd7a709ef5ef89b2b1f3b063270646bd12c81173b2e8/sqlite3/lib/binding/napi-v6-linux-glibc-x64/node_sqlite3.node]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 15: 0x7fb2a8090c1c node_sqlite3::Statement::Work_AfterAll(napi_env__*, napi_status, void*) [/tmp/pkg/1f8cc72dfb50f0c54b04dd7a709ef5ef89b2b1f3b063270646bd12c81173b2e8/sqlite3/lib/binding/napi-v6-linux-glibc-x64/node_sqlite3.node]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 16: 0x974b7a  [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 17: 0xafe4fd  [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 18: 0xb0dca5  [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 19: 0xb225fe  [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 20: 0x1044828  [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 21: 0x8fa323 node::SpinEventLoop(node::Environment*) [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 22: 0x9e1904 node::NodeMainInstance::Run(node::EnvSerializeInfo const*) [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 23: 0x96a36d node::Start(int, char**) [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 24: 0x7fb2aa47ed90  [/lib/x86_64-linux-gnu/libc.so.6]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 25: 0x7fb2aa47ee40 __libc_start_main [/lib/x86_64-linux-gnu/libc.so.6]
Sep 10 12:43:12 quickplex audiobookshelf[126767]: 26: 0x8ebd7c  [/usr/share/audiobookshelf/audiobookshelf]
Sep 10 12:43:12 quickplex systemd[1]: audiobookshelf.service: Main process exited, code=dumped, status=6/ABRT

Steps to reproduce the issue

  1. Upgrade to 2.4.1
  2. Select a podcast library
  3. Click on the library tab

Audiobookshelf version

2.4.1

How are you running audiobookshelf?

Debian/PPA

advplyr commented 1 year ago

Roughly how many episodes does your largest podcast have?

paxchristos commented 1 year ago

~3800 for the largest there are about 4 more in the ~750 -1k episode range

jrhedman commented 1 year ago

It looks like it's the same error as I see on a few issues so they're probably related:

FATAL ERROR: Reached heap limit Allocation failed - JavaScript heap out of memory

(I'm having the same issue and after updating to 2.4.1, I'm unable to open my podcast library without it crashing, unfortunately I didn't make note of version I was on previously).

I've been following this bug since this issue was created.

EDIT: My largest podcast has ~2175 episodes but it's not the culprit. I started getting this crash after adding a new podcast with ~670 episodes and it crashed after downloading half of them.

paxchristos commented 1 year ago

Famous last words: I use podgrab to download podcasts, so notionally audiobookshelf shouldn't be downloading podcasts automatically, only serving them.

jrhedman commented 1 year ago

Right, like I mentioned above, previously, my failure occurred when audiobookshelf was scheduled to download podcasts, but that doesn't mean it was failing at the downloading stage.

Since I'm failing when I open my podcast library as of now, I think it's the same error as before occurring when querying currently downloaded episodes (which it'd have to do to know what to download). That might explain why I'm seeing the error now after a fresh install as well.

@advplyr has noted in a few other places that maybe the sql query being done may need some optimization work for large folder.

Dragonatorul commented 10 months ago

I'm seeing the same issue. I'm on v2.3.3 because of the performance issues with 3.4

[2023-10-27 21:02:31] INFO: [PodcastManager] runEpisodeCheck: "Beau of The Fifth Column" | Last check: Thu Aug 03 2023 14:03:35 GMT+0300 (Eastern European Summer Time) | Latest episode pubDate: Thu Aug 03 2023 09:15:00 GMT+0300 (Eastern European Summer Time)

[2023-10-27 21:02:31] DEBUG: [PodcastManager] runEpisodeCheck: "Beau of The Fifth Column" checking for episodes after Thu Aug 03 2023 09:15:00 GMT+0300 (Eastern European Summer Time) (PodcastManager.js:248)

[2023-10-27 21:02:31] DEBUG: [podcastUtils] getPodcastFeed for "https://anchor.fm/s/cff1340/podcast/rss" (podcastUtils.js:206)

[2023-10-27 21:02:57] DEBUG: [podcastUtils] getPodcastFeed for "https://anchor.fm/s/cff1340/podcast/rss" success - parsing xml (podcastUtils.js:222)

[2023-10-27 21:03:01] DEBUG: [PodcastManager] runEpisodeCheck: 30 episodes found (PodcastManager.js:251)

[2023-10-27 21:03:01] INFO: [PodcastManager] Found 30 new episodes for podcast "Beau of The Fifth Column" - starting download

[2023-10-27 21:03:01] DEBUG: [Watcher] Ignoring directory "/podcasts/Beau of The Fifth Column" (Watcher.js:207)

[2023-10-27 21:03:03] DEBUG: [FfmpegHelpers] downloadPodcastEpisode: Cmd: ffmpeg -i pipe:0 -y -c copy -metadata podcast=1 -metadata album=Beau of The Fifth Column -metadata album-sort=Beau of The Fifth Column -metadata artist=Beau of The Fifth Column -metadata artist-sort=Beau of The Fifth Column -metadata comment=<p>Let's talk about water, ice, and Antarctica....</p>

--- 

Send in a voice message: https://podcasters.spotify.com/pod/show/beau-of-the-fifth-column/message

Support this podcast: <a href="https://podcasters.spotify.com/pod/show/beau-of-the-fifth-column/support">https://podcasters.spotify.com/pod/show/beau-of-the-fifth-column/support</a> -metadata genre=Society & Culture;Podcasts -metadata MVNM=Beau of The Fifth Column -metadata title=Let's talk about water, ice, and Antarctica.... -metadata title-sort=Let's talk about water, ice, and Antarctica.... -metadata year=2023 -metadata date=Fri, 27 Oct 2023 03:46:00 GMT -metadata releasedate=Fri, 27 Oct 2023 03:46:00 GMT -metadata itunes-id=1479080781 -metadata podcast-type=episodic /podcasts/Beau of The Fifth Column/Let's talk about water, ice, and Antarctica.... (c526e717-4c1f-4008-8d66-ef7a3ae89f3b).mp3 (ffmpegHelpers.js:151)

[2023-10-27 21:03:04] DEBUG: [FfmpegHelpers] downloadPodcastEpisode: Complete (ffmpegHelpers.js:158)

<--- Last few GCs --->

[1:0x7fb44c0e8410]  3608899 ms: Mark-sweep (reduce) 4081.8 (4114.8) -> 4081.8 (4114.8) MB, 72.9 / 0.0 ms  (+ 277.4 ms in 5 steps since start of marking, biggest step 77.2 ms, walltime since start of marking 398 ms) (average mu = 0.769, current mu = 0.340)[1:0x7fb44c0e8410]  3609180 ms: Mark-sweep (reduce) 4083.1 (4116.2) -> 4083.1 (4116.2) MB, 279.3 / 0.0 ms  (average mu = 0.611, current mu = 0.007) allocation failure scavenge might not succeed

<--- JS stacktrace --->

FATAL ERROR: Reached heap limit Allocation failed - JavaScript heap out of memory

Config /config /metadata

[2023-10-27 21:03:18] INFO: === Starting Server ===

[2023-10-27 21:03:18] INFO: [Server] Init v2.3.3

In my case it's happening when downloading new episodes for a very large podcast.

image

paxchristos commented 10 months ago

Just an update, crashing still happening with the same errors on 2.5.0 (docker)

jrhedman commented 10 months ago

@paxchristos

Try adding NODE_OPTIONS=--max_old_space_size=8192 back in your Environment Variables in your Docker Compose as mentioned in #1926.

This was removed a few releases ago since the OOM Crash was mostly resolved outside of edge cases like this.

paxchristos commented 10 months ago

@paxchristos

Try adding NODE_OPTIONS=--max_old_space_size=8192 back in your Environment Variables in your Docker Compose as mentioned in #1926.

I forgot that I left NODE_OPTIONS=--max_old_space_size=1024 in .env from testing before. Changing it from 1gb to 8gb allows library to load w/o crashing, but once I click into a ~3800 track podcast, it crashes w/ FATAL ERROR: Reached heap limit Allocation failed - JavaScript heap out of memory

jrhedman commented 10 months ago

...but once I click into a ~3800 track podcast, it crashes...

Is this when trying to download a 3800 track podcast list or opening an existing library?

I'm thinking it has something to do with loading all the track details into memory. Maybe we need to look into figuring out how to split this into batches since increasing space size for larger and larger libraries is a losing game.

aunefyren commented 10 months ago

redacted audio

I managed to be able to load the library of my podcast (1500 episodes) by increasing --max_old_space_size, but starting playback causes the socket to disconnect. Server is in debug mode, but basically nothing appears in the log. Network log on front end says NS_BINDING_ABORTED and finally 502 error.

Is this related at all? I am resuming playback from the homepage. Any other podcasts start just fine.

advplyr commented 10 months ago

@aunefyren That's unrelated since it's coming from cloudflare.

advplyr commented 10 months ago

Actually if the server is crashing then it is Abs, but not sure why cloudflare would return a 502. Note that the logs from Abs won't show errors that aren't caught. You would have to see those by looking at the container logs

aunefyren commented 10 months ago

Actually if the server is crashing then it is Abs, but not sure why cloudflare would return a 502. Note that the logs from Abs won't show errors that aren't caught. You would have to see those by looking at the container logs

I think when the Cloudflare proxy fails to connect to ABS (because it crashes) it gives a 502 error. If I disable Cloudflare proxy I just get NS_BINDING_ABORTED in the browser.

Sorry if I was unclear about logs. The server is in debug mode and the container logs is very empty for errors:

[2023-10-31 19:20:49] DEBUG: Loaded 3 personalized shelves in 0.21s (LibraryItem.js:667)
[2023-10-31 19:20:50] DEBUG: [SocketAuthority] User Offline aune (SocketAuthority.js:116)
[2023-10-31 19:20:50] INFO: [SocketAuthority] Socket AogDLsaKKA-0bBa0AAAb disconnected from client "aune" after 157343ms (Reason: transport close)
[2023-10-31 19:22:12] DEBUG: [PlaybackSessionManager] startSessionRequest for device Windows 10 / Chrome (PlaybackSessionManager.js:64)
[2023-10-31 19:22:12] DEBUG: [PlaybackSessionManager] "aune" starting direct play session for item "1bb7348e-41ff-490f-b33a-7c1ad1d6e432" with id ad6ce930-041c-4153-ba7b-dd17a42d9296 (Device: Windows 10 / Chrome) (PlaybackSessionManager.js:240)
[2023-10-31 19:23:13] DEBUG: [PlaybackSessionManager] syncSession "ad6ce930-041c-4153-ba7b-dd17a42d9296" (Device: Windows 10 / Chrome) | Total Time Listened: 20 (PlaybackSessionManager.js:276)
[2023-10-31 19:23:31] DEBUG: [PlaybackSessionManager] syncSession "ad6ce930-041c-4153-ba7b-dd17a42d9296" (Device: Windows 10 / Chrome) | Total Time Listened: 30 (PlaybackSessionManager.js:276)

In this timeframe I loaded the home page, resumed playback on a podcast with 1500 tracks, and had it stop syncing progress. Same behavior on Android app, except playback never starts.

I can open another issue or redirect my comment if this is unrelated.

advplyr commented 8 months ago

Updates were made in v2.7.1 for large podcast libraries. I'm not sure if the OOM issues will be resolved since I didn't change the data model but let me know if you get a chance to test v2.7.1

aunefyren commented 8 months ago

My playback issues are resolved.

jrhedman commented 8 months ago

Updates were made in v2.7.1 for large podcast libraries. I'm not sure if the OOM issues will be resolved since I didn't change the data model but let me know if you get a chance to test v2.7.1

Just updated and tested it out on both Web and iOS app and have no OOM issues now. Podcasts load much faster now as well.

Tested this on 2 sets of 1k+ episode podcasts.

Thanks @advplyr

jrhedman commented 8 months ago

@advplyr

A few day's have gone by and I've noticed I've gotten the OOM crash again, it looks like it's failing to clear the cache during parsing for new episodes to download.

...

2024/01/03 12:01:01,stdout,

2024/01/03 12:01:00,stdout,npm ERR!     /root/.npm/_logs/2024-01-03T16_16_31_334Z-debug-0.log

2024/01/03 12:01:00,stdout,npm ERR! A complete log of this run can be found in:

2024/01/03 12:01:00,stdout,

2024/01/03 12:01:00,stdout,npm ERR! command sh -c -- node index.js

2024/01/03 12:01:00,stdout,npm ERR! signal SIGABRT

2024/01/03 12:01:00,stdout,npm ERR! command failed

2024/01/03 12:01:00,stdout,npm ERR! path /

2024/01/03 12:00:40,stdout,FATAL ERROR: Reached heap limit Allocation failed - JavaScript heap out of memory

2024/01/03 12:00:40,stdout,

2024/01/03 12:00:40,stdout,<--- JS stacktrace --->

2024/01/03 12:00:40,stdout,

2024/01/03 12:00:40,stdout,

2024/01/03 12:00:40,stdout,"[17:0x7fce68b773f0]  2649106 ms: Mark-sweep (reduce) 2044.4 (2060.9) -> 2044.4 (2060.4) MB, 24.3 / 0.0 ms  (+ 41.5 ms in 3 steps since start of marking, biggest step 41.5 ms, walltime since start of marking 83 ms) (average mu = 0.988, current mu = 0.476) [17:0x7fce68b773f0]  2649236 ms: Mark-sweep (reduce) 2045.7 (2061.6) -> 2045.6 (2061.9) MB, 127.1 / 0.0 ms  (average mu = 0.962, current mu = 0.029) allocation failure scavenge might not succeed
"
2024/01/03 12:00:40,stdout,

2024/01/03 12:00:40,stdout,<--- Last few GCs --->

2024/01/03 12:00:40,stdout,

2024/01/03 12:00:32,stdout,[2024-01-03 17:00:32.516] DEBUG: [LibraryItem] Success saving abmetadata to "/metadata/items/c9ea4781-75ec-47fb-8923-d27f386f6081/metadata.json" (LibraryItem.js:310)

2024/01/03 12:00:32,stdout,[2024-01-03 17:00:32.510] DEBUG: [PodcastManager] No new episodes for "Stuff You Should Know" (PodcastManager.js:266)

2024/01/03 12:00:32,stdout,[2024-01-03 17:00:32.510] DEBUG: [PodcastManager] runEpisodeCheck: N/A episodes found (PodcastManager.js:247)

2024/01/03 12:00:29,stdout,[2024-01-03 17:00:29.918] DEBUG: [podcastUtils] getPodcastFeed for "https://www.omnycontent.com/d/playlist/e73c998e-6e60-432f-8610-ae210140c5b1/a91018a4-ea4f-4130-bf55-ae270180c327/44710ecc-10bb-48d1-93c7-ae270180c33e/podcast.rss" success - parsing xml (podcastUtils.js:254)

2024/01/03 12:00:29,stdout,[2024-01-03 17:00:29.397] DEBUG: [podcastUtils] getPodcastFeed for "https://www.omnycontent.com/d/playlist/e73c998e-6e60-432f-8610-ae210140c5b1/a91018a4-ea4f-4130-bf55-ae270180c327/44710ecc-10bb-48d1-93c7-ae270180c33e/podcast.rss" (podcastUtils.js:229)

2024/01/03 12:00:29,stdout,[2024-01-03 17:00:29.397] DEBUG: [PodcastManager] runEpisodeCheck: "Stuff You Should Know" checking for episodes after Wed Jan 03 2024 10:00:00 GMT+0000 (Coordinated Universal Time) (PodcastManager.js:244)

2024/01/03 12:00:29,stdout,[2024-01-03 17:00:29.397] INFO: [PodcastManager] runEpisodeCheck: "Stuff You Should Know" | Last check: Wed Jan 03 2024 14:01:32 GMT+0000 (Coordinated Universal Time) | Latest episode pubDate: Wed Jan 03 2024 10:00:00 GMT+0000 (Coordinated Universal Time)

2024/01/03 12:00:29,stdout,[2024-01-03 17:00:29.345] DEBUG: [ApiCacheManager] podcast.afterUpdate: Clearing cache (ApiCacheManager.js:21)

...
jucor commented 7 months ago

I'm on 2.7.2 and getting the same JavaScript heap out of memory error. I have been loading a lot of things: audiobooks and a lot of files from my podcast collection. Log of the docker file attached. Any idea how to prevent it, please? I have lots more RAM to spare on that machine, so would be happy with a setting to bump up the allocated RAM. _arr-audiobookshelf-1_logs.txt

I will try the environment variables from https://github.com/advplyr/audiobookshelf/issues/1926#issuecomment-1639020501 to tell node.js to augment its memory allocation, see if it helps.