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]: Delayed and/or failed playback of podcast/s #2979

Closed ahsee closed 4 months ago

ahsee commented 4 months ago

What happened?

Attempting to playback on remote (LAN) devices either failing or severely delayed.

Noted repeated errors:

File path does not exist /usr/share/audiobookshelf/metadata/streams/ac762f66-d880-44a0-9027-be858a3686aa/output-553.ts No Segments.

Unsure of where to look to resolve this. It seems like the transcode is long-running or severely delayed?

What did you expect to happen?

Playback is achieved with minimal delays.

Steps to reproduce the issue

  1. Play podcast episode

Audiobookshelf version

v2.9.0 Debian

How are you running audiobookshelf?

Debian/PPA

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?

Other (list in "Additional Notes" box)

Logs

{"timestamp":"2024-05-15 11:32:06.672","source":"    at Logger.setLogLevel (/snapshot/audiobookshelf/server/Logger.js)","message":"Set Log Level to DEBUG","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:32:06.676","source":"    at ApiCacheManager.clear (/snapshot/audiobookshelf/server/managers/ApiCacheManager.js)","message":"[ApiCacheManager] Array.afterUpsert: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:32:08.610","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"[STREAM-CHECK] Check Files 123 of 753 16.33% Furthest Segment: 670","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:32:10.494","source":"    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"[FFMPEG] Transcoding ended","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:32:14.854","source":"    at ApiCacheManager.clear (/snapshot/audiobookshelf/server/managers/ApiCacheManager.js)","message":"[ApiCacheManager] Object.afterBulkUpdate: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:32:14.855","source":"    at PlaybackSessionManager.startSessionRequest (/snapshot/audiobookshelf/server/managers/PlaybackSessionManager.js)","message":"[PlaybackSessionManager] startSessionRequest for device SM-G781B SDK 33 / v13","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:32:14.855","source":"    at PlaybackSessionManager.startSession (/snapshot/audiobookshelf/server/managers/PlaybackSessionManager.js)","message":"[PlaybackSessionManager] startSession: Closing open session \"Podcast Episode (5/5/2024)\" for user \"username\" (Device: SM-G781B SDK 33 / v13)","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:32:14.855","source":"    at PlaybackSessionManager.closeSession (/snapshot/audiobookshelf/server/managers/PlaybackSessionManager.js)","message":"[PlaybackSessionManager] closeSession \"2f230024-6f36-4c76-9b69-0f31bd8a283f\"","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:32:14.856","source":"    at Stream.close (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"Closing Stream 2f230024-6f36-4c76-9b69-0f31bd8a283f","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:32:14.868","source":"    at /snapshot/audiobookshelf/server/objects/Stream.js","message":"Deleted session data /usr/share/audiobookshelf/metadata/streams/2f230024-6f36-4c76-9b69-0f31bd8a283f","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:32:14.869","source":"    at Stream.<anonymous> (/snapshot/audiobookshelf/server/managers/PlaybackSessionManager.js)","message":"[PlaybackSessionManager] Stream closed for session \"2f230024-6f36-4c76-9b69-0f31bd8a283f\" (Device: SM-G781B SDK 33 / v13)","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:32:14.869","source":"    at PlaybackSessionManager.removeSession (/snapshot/audiobookshelf/server/managers/PlaybackSessionManager.js)","message":"[PlaybackSessionManager] Removed session \"2f230024-6f36-4c76-9b69-0f31bd8a283f\"","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:32:14.870","source":"    at PlaybackSessionManager.startSession (/snapshot/audiobookshelf/server/managers/PlaybackSessionManager.js)","message":"[PlaybackSessionManager] \"username\" starting direct play session for item \"7fb1a2f8-49dd-4f25-9411-be705a41efd1\" with id b16be9a3-c902-4dea-9ae3-819581dc073b (Device: SM-G781B SDK 33 / v13)","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:32:15.065","source":"    at /snapshot/audiobookshelf/server/Server.js","message":"Received ping","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:32:50.092","source":"    at ApiCacheManager.clear (/snapshot/audiobookshelf/server/managers/ApiCacheManager.js)","message":"[ApiCacheManager] Object.afterBulkUpdate: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:32:50.092","source":"    at PlaybackSessionManager.startSessionRequest (/snapshot/audiobookshelf/server/managers/PlaybackSessionManager.js)","message":"[PlaybackSessionManager] startSessionRequest for device SM-G781B SDK 33 / v13","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:32:50.093","source":"    at PlaybackSessionManager.startSession (/snapshot/audiobookshelf/server/managers/PlaybackSessionManager.js)","message":"[PlaybackSessionManager] startSession: Closing open session \"Podcast Episode (5/5/2024)\" for user \"username\" (Device: SM-G781B SDK 33 / v13)","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:32:50.093","source":"    at PlaybackSessionManager.closeSession (/snapshot/audiobookshelf/server/managers/PlaybackSessionManager.js)","message":"[PlaybackSessionManager] closeSession \"b16be9a3-c902-4dea-9ae3-819581dc073b\"","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:32:50.094","source":"    at PlaybackSessionManager.removeSession (/snapshot/audiobookshelf/server/managers/PlaybackSessionManager.js)","message":"[PlaybackSessionManager] Removed session \"b16be9a3-c902-4dea-9ae3-819581dc073b\"","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:32:50.094","source":"    at PlaybackSessionManager.startSession (/snapshot/audiobookshelf/server/managers/PlaybackSessionManager.js)","message":"[PlaybackSessionManager] \"username\" starting stream session for item \"7fb1a2f8-49dd-4f25-9411-be705a41efd1\" (Device: SM-G781B SDK 33 / v13)","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:32:50.097","source":"    at Stream.start (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"[STREAM] START STREAM - Num Segments: 753","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:32:50.100","source":"    at Stream.start (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"[STREAM] Starting Stream at startTime 54:52.0 (User startTime 55:22.0) and Segment #548","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:32:50.109","source":"    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"[INFO] FFMPEG transcoding started with command: ffmpeg -seek_timestamp 1 -f concat -safe 0 -ss 3292.3s -noaccurate_seek -i /usr/share/audiobookshelf/metadata/streams/ac762f66-d880-44a0-9027-be858a3686aa/files.txt -y -loglevel error -map 0:a -c:a copy -f hls -copyts -avoid_negative_ts make_non_negative -max_delay 5000000 -max_muxing_queue_size 2048 -hls_time 6 -hls_segment_type mpegts -start_number 548 -hls_playlist_type vod -hls_list_size 0 -hls_allow_cache 0 -hls_segment_filename /usr/share/audiobookshelf/metadata/streams/ac762f66-d880-44a0-9027-be858a3686aa/output-%d.ts /usr/share/audiobookshelf/metadata/streams/ac762f66-d880-44a0-9027-be858a3686aa/final-output.m3u8","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:32:50.109","source":"    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:32:50.217","source":"    at HlsRouter.streamFileRequest (/snapshot/audiobookshelf/server/routers/HlsRouter.js)","message":"File path does not exist /usr/share/audiobookshelf/metadata/streams/ac762f66-d880-44a0-9027-be858a3686aa/output-553.ts","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:32:50.231","source":"    at HlsRouter.streamFileRequest (/snapshot/audiobookshelf/server/routers/HlsRouter.js)","message":"File path does not exist /usr/share/audiobookshelf/metadata/streams/ac762f66-d880-44a0-9027-be858a3686aa/output-553.ts","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:32:51.266","source":"    at HlsRouter.streamFileRequest (/snapshot/audiobookshelf/server/routers/HlsRouter.js)","message":"File path does not exist /usr/share/audiobookshelf/metadata/streams/ac762f66-d880-44a0-9027-be858a3686aa/output-553.ts","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:32:52.110","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:32:53.298","source":"    at HlsRouter.streamFileRequest (/snapshot/audiobookshelf/server/routers/HlsRouter.js)","message":"File path does not exist /usr/share/audiobookshelf/metadata/streams/ac762f66-d880-44a0-9027-be858a3686aa/output-553.ts","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:32:54.110","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:32:56.111","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:32:58.111","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:33:00.111","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:33:02.111","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:33:04.111","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:33:06.111","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:33:08.112","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:33:10.113","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:33:12.113","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:33:14.113","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:33:16.114","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:33:18.114","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:33:20.114","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:33:22.114","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"No Segments","levelName":"WARN","level":3}
{"timestamp":"2024-05-15 11:33:24.114","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"[STREAM] ac762f66-d880-44a0-9027-be858a3686aa notifying client that stream is ready","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:33:24.116","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"[STREAM-CHECK] Check Files 58 of 753 7.70% Furthest Segment: 605","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:33:26.115","source":"    at Stream.checkFiles (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"[STREAM-CHECK] Check Files 146 of 753 19.39% Furthest Segment: 693","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:33:27.291","source":"    at FfmpegCommand.<anonymous> (/snapshot/audiobookshelf/server/objects/Stream.js)","message":"[FFMPEG] Transcoding ended","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:33:42.566","source":"    at Logger.setLogLevel (/snapshot/audiobookshelf/server/Logger.js)","message":"Set Log Level to DEBUG","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:33:42.570","source":"    at ApiCacheManager.clear (/snapshot/audiobookshelf/server/managers/ApiCacheManager.js)","message":"[ApiCacheManager] Array.afterUpsert: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:35:52.810","source":"    at Socket.<anonymous> (/snapshot/audiobookshelf/server/SocketAuthority.js)","message":"[SocketAuthority] User Offline username","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:35:52.811","source":"    at Socket.<anonymous> (/snapshot/audiobookshelf/server/SocketAuthority.js)","message":"[SocketAuthority] Socket okkmD7prql60fG9jAAAP disconnected from client \"username\" after 296118ms (Reason: ping timeout)","levelName":"INFO","level":2}
{"timestamp":"2024-05-15 11:36:21.570","source":"    at ApiCacheManager.clear (/snapshot/audiobookshelf/server/managers/ApiCacheManager.js)","message":"[ApiCacheManager] Array.afterUpsert: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:36:30.659","source":"    at ApiCacheManager.clear (/snapshot/audiobookshelf/server/managers/ApiCacheManager.js)","message":"[ApiCacheManager] Array.afterUpsert: Clearing cache","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:37:14.458","source":"    at Socket.<anonymous> (/snapshot/audiobookshelf/server/SocketAuthority.js)","message":"[SocketAuthority] User Offline username","levelName":"DEBUG","level":1}
{"timestamp":"2024-05-15 11:37:14.459","source":"    at Socket.<anonymous> (/snapshot/audiobookshelf/server/SocketAuthority.js)","message":"[SocketAuthority] Socket gwv1_pqLNxxllpPaAAAN disconnected from client \"username\" after 754110ms (Reason: transport close)","levelName":"INFO","level":2}

Additional Notes

I am noting delayed playback on browser also.

Audiobookshelf is running on a Debian LXC in Proxmox.

advplyr commented 4 months ago

Does this happen with different podcast episodes? The transcode only happens if the file cannot be direct played. Then it tries to fallback to transcoding. Please share more information about the specific file being played and preferably the podcast so the issue can be replicated.

ahsee commented 4 months ago

Thanks - but nevermind 😅 Host had flooded IO bandwidth.