[Bug]: Podcast cron infinite hang

[SuperEllipsis]

What happened?

Sometimes when the server has been running for a while, it seems to hang on it self, with a simple message of "[CronManager] Podcast cron "0 * * * *" is already executing", it will not download more podcasts from the RSS feeds automatically, until the docker container is restarted. I can still go through each manually and download the episodes from the RSS feed

What did you expect to happen?

I expected it to potentially throw an error/warning in the logs, if it was hanging, and then retry later

Steps to reproduce the issue

I am unsure of when and how it happens, but usually it is just

1. Setup podcasts with RSS feed to automatically try to pull every hour (standard)
2. Wait a couple of days
3. Automatic download stops working

Audiobookshelf version

v2.19.5

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

Additional Notes

No response

[Vito0912]

Could you please enable debug logging (top right) and check if there is anything in the logs after a server restart and the first scan?

[SuperEllipsis]

Good catch, I will do that. And update, if I find something in the debug logs

[SuperEllipsis]

I restarted the server, and set the log level to debug. And a couple of days later, it failed again.
Here is the log from the day, where the "Podcast cron "0 * * * *" is already executing" starts to appear
2025-03-13.txt

Specifically, here is a selection of message right as the warning starts (full logs in file above):

{"timestamp":"2025-03-13 02:00:51.069","source":"CronManager.js:208","message":"[CronManager] Finished executing podcast cron 0 * * * * for 22 item(s)","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 03:00:00.099","source":"CronManager.js:179","message":"[CronManager] Start executing podcast cron 0 * * * * for 22 item(s)","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 03:00:04.360","source":"PodcastManager.js:316","message":"[PodcastManager] runEpisodeCheck: \"SAKURA TIPS｜Listen to Japanese\" | Last check: Thu Mar 13 2025 02:00:02 GMT+0000 (Coordinated Universal Time) | Latest episode pubDate: Sat Jun 08 2024 07:20:00 GMT+0000 (Coordinated Universal Time)","levelName":"INFO","level":2}
{"timestamp":"2025-03-13 03:00:04.360","source":"PodcastManager.js:321","message":"[PodcastManager] runEpisodeCheck: \"SAKURA TIPS｜Listen to Japanese\" checking for episodes after Sat Jun 08 2024 07:20:00 GMT+0000 (Coordinated Universal Time)","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 03:00:04.361","source":"podcastUtils.js:298","message":"[podcastUtils] getPodcastFeed for \"https://anchor.fm/s/3c2daac8/podcast/rss\"","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 03:00:04.468","source":"podcastUtils.js:334","message":"[podcastUtils] getPodcastFeed for \"https://anchor.fm/s/3c2daac8/podcast/rss\" success - parsing xml","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 03:00:05.133","source":"PodcastManager.js:324","message":"[PodcastManager] runEpisodeCheck: N/A episodes found","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 03:00:05.145","source":"PodcastManager.js:344","message":"[PodcastManager] No new episodes for \"SAKURA TIPS｜Listen to Japanese\"","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 03:00:05.747","source":"ApiCacheManager.js:20","message":"[ApiCacheManager] podcast.afterUpdate: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 03:00:06.241","source":"ApiCacheManager.js:20","message":"[ApiCacheManager] libraryItem.afterUpdate: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 03:00:06.326","source":"PodcastManager.js:316","message":"[PodcastManager] runEpisodeCheck: \"Japanese podcast for beginners (Nihongo con Teppei)\" | Last check: Thu Mar 13 2025 02:00:08 GMT+0000 (Coordinated Universal Time) | Latest episode pubDate: Wed Mar 12 2025 23:13:43 GMT+0000 (Coordinated Universal Time)","levelName":"INFO","level":2}
{"timestamp":"2025-03-13 03:00:06.326","source":"PodcastManager.js:321","message":"[PodcastManager] runEpisodeCheck: \"Japanese podcast for beginners (Nihongo con Teppei)\" checking for episodes after Wed Mar 12 2025 23:13:43 GMT+0000 (Coordinated Universal Time)","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 03:00:06.326","source":"podcastUtils.js:298","message":"[podcastUtils] getPodcastFeed for \"https://nihongoconteppei.com/feed/podcast/\"","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 04:00:00.996","source":"CronManager.js:155","message":"[CronManager] Podcast cron \"0 * * * *\" is already executing","levelName":"WARN","level":3}
{"timestamp":"2025-03-13 05:00:00.597","source":"CronManager.js:155","message":"[CronManager] Podcast cron \"0 * * * *\" is already executing","levelName":"WARN","level":3}
{"timestamp":"2025-03-13 06:00:00.124","source":"CronManager.js:155","message":"[CronManager] Podcast cron \"0 * * * *\" is already executing","levelName":"WARN","level":3}
{"timestamp":"2025-03-13 07:00:00.674","source":"CronManager.js:155","message":"[CronManager] Podcast cron \"0 * * * *\" is already executing","levelName":"WARN","level":3}
{"timestamp":"2025-03-13 08:00:00.290","source":"CronManager.js:155","message":"[CronManager] Podcast cron \"0 * * * *\" is already executing","levelName":"WARN","level":3}
{"timestamp":"2025-03-13 09:00:00.937","source":"CronManager.js:155","message":"[CronManager] Podcast cron \"0 * * * *\" is already executing","levelName":"WARN","level":3}
{"timestamp":"2025-03-13 10:00:00.536","source":"CronManager.js:155","message":"[CronManager] Podcast cron \"0 * * * *\" is already executing","levelName":"WARN","level":3}
{"timestamp":"2025-03-13 11:00:00.160","source":"CronManager.js:155","message":"[CronManager] Podcast cron \"0 * * * *\" is already executing","levelName":"WARN","level":3}
{"timestamp":"2025-03-13 11:43:46.965","source":"ApiCacheManager.js:48","message":"[ApiCacheManager] count: 0 size: 0","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 11:43:46.972","source":"ApiCacheManager.js:59","message":"[ApiCacheManager] Cache miss: {\"user\":\"jultu\",\"url\":\"/libraries\"}","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 11:43:47.004","source":"ApiCacheManager.js:48","message":"[ApiCacheManager] count: 1 size: 2433","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 11:43:47.004","source":"ApiCacheManager.js:51","message":"[ApiCacheManager] Cache hit: {\"user\":\"jultu\",\"url\":\"/libraries\"}","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 11:43:47.022","source":"ApiCacheManager.js:48","message":"[ApiCacheManager] count: 1 size: 2433","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 11:43:47.049","source":"ApiCacheManager.js:48","message":"[ApiCacheManager] count: 1 size: 2433","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 11:43:47.049","source":"ApiCacheManager.js:51","message":"[ApiCacheManager] Cache hit: {\"user\":\"jultu\",\"url\":\"/libraries\"}","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-13 11:43:47.060","source":"ApiCacheManager.js:48","message":"[ApiCacheManager] count: 1 size: 2433","levelName":"DEBUG","level":1}

[shimeike]

I am seeing this same issue exactly as described and with same setup as @SuperEllipsis .

Only abnormality in the logs (other than those same Cronmanager warnings once the issue has occurred) are some episode data errors for some feeds. I guess these have always been there and likely don't relate to the issue.

2025-03-18 20:00:42.213 ERROR [podcastUtils] Invalid podcast episode data

I've setup a cron job to restart the container daily as a workaround for now. Will report back if I see anything else of use in the logs. For now, just wanted to establish that the original report is not an isolated case.

[Vito0912]

Do you have set a custom PodcastDownloadTimeout?

[shimeike]

Do you have set a custom PodcastDownloadTimeout?

Do you mean PODCAST_DOWNLOAD_TIMEOUT environment variable? If so, no I do not have this set in my docker-compose.

[SuperEllipsis]

I have looked through the logs from the last few restarts. If it helps, it seems that the following RSS feed, might be causing the trouble for my setup: "https://nihongoconteppei.com/feed/podcast/". It might infact coincide with the release of a new episode, the dates for when ABS stops downloading is the same day, as new releases on their website (so far at least).

It has been the same line every time, right before the warnings starts:

{"timestamp":"2025-03-20 18:00:09.174","source":"podcastUtils.js:298","message":"[podcastUtils] getPodcastFeed for \"https://nihongoconteppei.com/feed/podcast/\"","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-20 19:00:02.680","source":"CronManager.js:155","message":"[CronManager] Podcast cron \"0 * * * *\" is already executing","levelName":"WARN","level":3}
...
{"timestamp":"2025-03-23 11:00:03.835","source":"podcastUtils.js:298","message":"[podcastUtils] getPodcastFeed for \"https://nihongoconteppei.com/feed/podcast/\"","levelName":"DEBUG","level":1}
{"timestamp":"2025-03-23 12:00:00.425","source":"CronManager.js:155","message":"[CronManager] Podcast cron \"0 * * * *\" is already executing","levelName":"WARN","level":3}

[Vito0912]

Yeah, I saw that too. I cannot reproduce it on my site. And if I looked up correctly, the code stops working where it physically should not be able to be stuck.
The only conclusion I had, was that the timeout does not get triggered. Any error, timeout, success would result in a log entry.
But the timeout also seems also not to be the problem

[SuperEllipsis]

It is quite weird. I might try to setup another instance on some alternative server equipment I have laying around, and see if it triggers on that as well. Or if I might have to try and clean / migrate to a new ABS instance.

[lodesmets]

Hey all, I have had the same issue multiple times, but usually the logs got deleted, because I only noticed the issue after a while. But now I have some logs

2025-04-15T04:00:00.779112000Z [2025-04-15 04:00:00.778] DEBUG: [CronManager] Start executing podcast cron 0 */2 * * * for 10 item(s)
2025-04-15T04:00:00.929989541Z [2025-04-15 04:00:00.929] INFO: [PodcastManager] runEpisodeCheck: "A Podcast Of Unnecessary Detail" | Last check: Tue Apr 15 2025 02:00:00 GMT+0000 (Coordinated Universal Time) | Latest episode pubDate: Tue Nov 19 2024 06:00:48 GMT+0000 (Coordinated Universal Time)
2025-04-15T04:00:01.119984782Z [2025-04-15 04:00:00.930] DEBUG: [PodcastManager] runEpisodeCheck: "A Podcast Of Unnecessary Detail" checking for episodes after Tue Nov 19 2024 06:00:48 GMT+0000 (Coordinated Universal Time)
2025-04-15T04:00:01.120075892Z [2025-04-15 04:00:00.930] DEBUG: [podcastUtils] getPodcastFeed for "https://feeds.acast.com/public/shows/61deed94f2acc80013aab8aa"
2025-04-15T04:00:01.120129152Z [2025-04-15 04:00:01.013] DEBUG: [podcastUtils] getPodcastFeed for "https://feeds.acast.com/public/shows/61deed94f2acc80013aab8aa" success - parsing xml
2025-04-15T04:00:01.120173322Z [2025-04-15 04:00:01.057] DEBUG: [PodcastManager] runEpisodeCheck: N/A episodes found
2025-04-15T04:00:01.120211072Z [2025-04-15 04:00:01.058] DEBUG: [PodcastManager] No new episodes for "A Podcast Of Unnecessary Detail"
2025-04-15T04:00:01.120249742Z [2025-04-15 04:00:01.074] DEBUG: [ApiCacheManager] podcast.afterUpdate: Clearing cache
2025-04-15T04:00:01.120287192Z [2025-04-15 04:00:01.093] DEBUG: [ApiCacheManager] libraryItem.afterUpdate: Clearing cache
2025-04-15T04:00:01.120319182Z [2025-04-15 04:00:01.094] INFO: [PodcastManager] runEpisodeCheck: "Nerdland maandoverzicht wetenschap en technologie" | Last check: Tue Apr 15 2025 02:00:05 GMT+0000 (Coordinated Universal Time) | Latest episode pubDate: Wed Apr 02 2025 00:00:00 GMT+0000 (Coordinated Universal Time)
2025-04-15T04:00:01.120373092Z [2025-04-15 04:00:01.095] DEBUG: [PodcastManager] runEpisodeCheck: "Nerdland maandoverzicht wetenschap en technologie" checking for episodes after Wed Apr 02 2025 00:00:00 GMT+0000 (Coordinated Universal Time)
2025-04-15T04:00:01.120413732Z [2025-04-15 04:00:01.095] DEBUG: [podcastUtils] getPodcastFeed for "https://feeds.soundcloud.com/users/soundcloud:users:293803449/sounds.rss"
2025-04-15T05:54:31.145305874Z [2025-04-15 05:54:31.145] DEBUG: [ApiCacheManager] count: 0 size: 0
2025-04-15T05:54:31.149635920Z [2025-04-15 05:54:31.149] DEBUG: [ApiCacheManager] Cache miss: {"user":"lode","url":"/libraries"}
2025-04-15T05:54:31.242743086Z [2025-04-15 05:54:31.242] DEBUG: [ApiCacheManager] count: 1 size: 1831
2025-04-15T05:54:31.254441586Z [2025-04-15 05:54:31.254] DEBUG: Loaded filterdata in 0.01s
2025-04-15T05:54:31.256523004Z [2025-04-15 05:54:31.256] DEBUG: [ApiCacheManager] Cache miss: {"user":"lode","url":"/libraries/bf5b3c58-57c5-462c-8422-05a9f08029f2?include=filterdata"}
2025-04-15T05:54:31.294295604Z [2025-04-15 05:54:31.294] INFO: [SocketAuthority] Socket Connected to /socket.io ZBhhlqKKj836c9NyAABf
2025-04-15T05:54:31.357252683Z [2025-04-15 05:54:31.357] DEBUG: [SocketAuthority] User Online lode
2025-04-15T05:54:31.416417556Z [2025-04-15 05:54:31.416] DEBUG: [ApiCacheManager] count: 2 size: 3283
2025-04-15T05:54:31.437837588Z [2025-04-15 05:54:31.437] DEBUG: Loaded 2 of 2 items for "Continue Listening/Reading" in 0.02s
2025-04-15T05:54:31.459463161Z [2025-04-15 05:54:31.459] DEBUG: Loaded 10 of 37 episodes for "Newest Episodes" in 0.02s
2025-04-15T05:54:31.468409474Z [2025-04-15 05:54:31.468] DEBUG: Loaded 0 of 0 items for "Recently Added" in 0.01s
2025-04-15T05:54:31.496421551Z [2025-04-15 05:54:31.496] DEBUG: Loaded 10 of 210 items for "Listen/Read Again" in 0.03s
2025-04-15T05:54:31.496770661Z [2025-04-15 05:54:31.496] DEBUG: Loaded 3 personalized shelves in 0.08s
2025-04-15T05:54:31.500838158Z [2025-04-15 05:54:31.500] DEBUG: [ApiCacheManager] Cache miss: {"user":"lode","url":"/libraries/bf5b3c58-57c5-462c-8422-05a9f08029f2/personalized?minified=1&include=rssfeed,numEpisodesIncomplete"}
2025-04-15T05:54:31.501034778Z [2025-04-15 05:54:31.500] DEBUG: [ApiCacheManager] Caching with 1800000 ms TTL
2025-04-15T05:54:31.840688454Z [2025-04-15 05:54:31.840] DEBUG: [ApiCacheManager] count: 3 size: 171124
2025-04-15T05:54:31.853364504Z [2025-04-15 05:54:31.853] DEBUG: Filter data for fd2aac77-afb2-4893-b3ab-b48080bbbea6 has not changed, returning cached data and updating cache time after 0.01s
2025-04-15T05:54:31.855977402Z [2025-04-15 05:54:31.855] DEBUG: [ApiCacheManager] Cache miss: {"user":"lode","url":"/libraries/fd2aac77-afb2-4893-b3ab-b48080bbbea6?include=filterdata"}
2025-04-15T05:54:32.427387772Z [2025-04-15 05:54:32.427] DEBUG: [ApiCacheManager] Object.afterBulkUpdate: Clearing cache
2025-04-15T05:54:32.427776762Z [2025-04-15 05:54:32.427] INFO: [PlaybackSessionManager] Syncing local session "131: Very happy mice" (393e01d5-e6e7-470a-adb3-f1c63ee28faa)
2025-04-15T05:54:32.457246778Z [2025-04-15 05:54:32.457] DEBUG: [PlaybackSessionManager] Updated session for "131: Very happy mice" (393e01d5-e6e7-470a-adb3-f1c63ee28faa)
2025-04-15T05:54:32.471508137Z [2025-04-15 05:54:32.471] DEBUG: [ApiCacheManager] Object.afterBulkUpdate: Clearing cache
2025-04-15T05:54:32.471871396Z [2025-04-15 05:54:32.471] DEBUG: [PlaybackSessionManager] Not updating progress for "131: Very happy mice" because it has been updated more recently
2025-04-15T05:58:34.950955528Z [2025-04-15 05:58:34.950] DEBUG: [SocketAuthority] User Offline lode
2025-04-15T05:58:34.951418708Z [2025-04-15 05:58:34.951] INFO: [SocketAuthority] Socket ZBhhlqKKj836c9NyAABf disconnected from client "lode" after 243658ms (Reason: transport close)
2025-04-15T05:58:40.610895954Z [2025-04-15 05:58:40.610] INFO: [SocketAuthority] Socket Connected to /socket.io h9B4p7UyDXmL3MzeAABh
2025-04-15T05:58:40.676533371Z [2025-04-15 05:58:40.676] DEBUG: [SocketAuthority] User Online lode
2025-04-15T06:00:00.872520702Z [2025-04-15 06:00:00.872] WARN: [CronManager] Podcast cron "0 */2 * * *" is already executing

It looks like ABS is trying to get the feed, but then it hangs
(2025-04-15T04:00:01.120413732Z [2025-04-15 04:00:01.095] DEBUG: [podcastUtils] getPodcastFeed for "https://feeds.soundcloud.com/users/soundcloud:users:293803449/sounds.rss")

[lodesmets]

I don't know what changed in the latest couple versions. But I have version 2.20.0, and the issue happens quite often (at least once a week)