philippe44 / LMS-Cast

Chromecast to LMS bridge
65 stars 10 forks source link

Longs tracks (e.g. podcasts) stopping after ~14 minutes #32

Closed askvictor closed 1 year ago

askvictor commented 1 year ago

When I play long tracks (e.g. podcast) over an LMS-Cast device, it stops playing after about 13-14 minutes. The same track played on a Squeezebox Radio plays fine all the way through.

Below is a snippet of the castbridge.log file:

[15:08:29.224] CastStop:309 [0x646168]: Stop w/o session or connect
[15:08:31.082] sq_callback:389 [0x646168]: LMS volume (0..128) 30 => CC 0.3700
[15:08:31.087] process_strm:228 [0x5b2710] strm command s
[15:08:31.087] process_strm:295 [0x5b2710], strm s autostart: 3 transition period: 10 transition type: 0 codec: m
[15:08:31.087] sendSTAT:159 [0x5b2710]: STAT:[STMf] msplayed 0
[15:08:31.099] sq_callback:307 [0x646168]:
        artist:
        album:
        title:Ports of Paradise 2023-11-03
        genre:
        duration:7442.336
        size:0
        cover:https://amrap-pages-image.s3.amazonaws.com/profile/6929.jpg?cacbeb=76296129
        offset:0
[15:08:31.101] LaunchReceiver:188 [0x646168]: Launching receiver 1
[15:08:31.101] CastLoad:177 [0x646168]: Queuing LOAD
[15:08:31.101] sq_callback:336 [0x646168]: current URI (s:0) http://192.168.1.11:53903/bridge-1.mp3
[15:08:31.101] process_start:1245 [0x5b2710]: codec:*, ch:0, s:0, r:0
[15:08:31.131] sendSTAT:159 [0x5b2710]: STAT:[STMc] msplayed 0
[15:08:31.132] sq_callback:389 [0x646168]: LMS volume (0..128) 30 => CC 0.3700
[15:08:31.350] CastSetDeviceVolume:373 [0x646168]: Queuing SET_VOLUME
[15:08:31.350] CastPlay:262 [0x646168]: Queuing PLAY
[15:08:33.902] CastSocketThread:656 [0x646168]: Receiver launched
[15:08:33.902] ProcessQueue:483 [0x646168]: Processing LOAD (id:2)
[15:08:34.321] CastSocketThread:670 [0x646168]: Media session id 1
[15:08:34.384] ProcessQueue:448 [0x646168]: Processing VOLUME (id:5)
[15:08:34.442] ProcessQueue:455 [0x646168]: Processing PLAY (id:6)
[15:08:34.541] _SyncNotifyState:475 [0x646168]: Cast playing
[15:08:35.541] sendSTAT:159 [0x5b2710]: STAT:[STMs] msplayed 0
[15:22:36.308] _SyncNotifyState:446 [0x646168]: Cast stop
[15:22:36.308] slimproto_run:760 [0x5b2710]: Track shorter than expected (840341/7442336)
[15:22:36.308] sendSTAT:159 [0x5b2710]: STAT:[STMd] msplayed 840341
[15:22:36.309] sendSTAT:159 [0x5b2710]: STAT:[STMu] msplayed 840341
[15:23:05.311] MRThread:653 [0x646168]: Idle timeout, releasing cast device
[15:23:32.002] slimproto_run:562 [0x5b2710] Closing CLI socket 7

The issue seems to be the "Track shorter than expected" - any ideas?

philippe44 commented 1 year ago

Yes, it is likely an issue with the podcast provider web server. Cast devices tend to have very large buffers and they initially acquire a large portion of the podcast and then can be idle for a long while before requesting more data. Some servers tend to think that the connection went stalled and close it. In fact, a lot of servers expect clients to download the whole podcast at once and play it at their own pace, they don't want to "live stream" podcasts for very understandable reasons.

This problem is a general issue with LMS but it can be less visible with some players that either have smaller buffers or tend to grab a large initial amount and then regularly require small chunks when their level is depleted enough. But that "high/low water" mechanism can happen with a very large difference between high and low water.

So, to cut the long story short, I did implement directly in LMS two options to work around this. You'll find them in the "Settings", tab "Advanced", option "Network". It's the "HTTP(s) streaming mode" option. It speaks for itself.

askvictor commented 1 year ago

Thank you - I've set it to cache mode and that's fixed it. I had been poking around the Cast Bridge options thinking it was specific to that, but hadn't thought to look elsewhere.