Music streaming stops intermittently

[thickasabrick]

Hi Raphy,

Thank you for maintaining Squeezelite! It's a great piece of software.

Sorry to resurrect an old thread, but I wanted to express interest in squashing this bug if you were game to keep digging. My details:

* intermittent pauses in playback, about 20s long
* seems to happen most with long, low-bitrate, fixed-length (but streamed) content (ex. podcasts)
* occurs regardless of the "Cache HTTP(S) streams on disk" option in LMS
* a playerOutputUnderrun is logged in LMS and an STMo in Squeezelite
* the bug does not occur when a large streambuf value is used (-b 524288)
* both LMS (v8.2.0) and Squeezelite (v1.9.9-1392) are hosted on the same Windows 10 machine

With a small streambuf value of 262144 (my other command line flags are -r 96000-96000 -R vLE), the bug is reproducible by seeking to the last 30 minutes of this file and playing to the end: https://traffic.libsyn.com/secure/thebestshow/TBS_010422.mp3?dest-id=232563

Here's an example where LMS reports that it's reached the end of the stream:

[22-01-14 15:54:35.8045] Slim::Player::Source::_readNextChunk (378) end of file or error on socket, song pos: 108940249
[22-01-14 15:54:35.8048] Slim::Player::Source::_readNextChunk (383) b0:6e:bf:c1:42:ef mark end of stream
[22-01-14 15:54:35.8060] Slim::Player::StreamingController::_setStreamingState (2386) new streaming state STREAMOUT

This is the last message from stream_thread until the interruption:

[15:56:36.037] stream_thread:428 streambuf read 1800 bytes

streambuf is entirely full:

[15:56:37.015] sendSTAT:200 received bytesL: 17235672 streambuf: 253143 outputbuf: 6478080 calc elapsed: 1689681 real elapsed: 1689703 (diff: -22) device: 29 delay: 31

streambuf now begins to drain:

[15:56:49.477] decode_thread:75 streambuf bytes: 129663 outputbuf space: 684959

1863 bytes seem to be stuck in the streambuf, however:

[15:57:04.005] sendSTAT:200 received bytesL: 17235672 streambuf: 1863 outputbuf: 5025120 calc elapsed: 1716670 real elapsed: 1716687 (diff: -17) device: 29 delay: 0

outputbuf is almost drained:

[15:57:10.010] sendSTAT:200 received bytesL: 17235672 streambuf: 1863 outputbuf: 432480 calc elapsed: 1722666 real elapsed: 1722703 (diff: -37) device: 29 delay: 16

outputbuf has underrun:

[15:57:11.011] sendSTAT:195 STAT: STMo
[15:57:11.011] sendSTAT:200 received bytesL: 17235672 streambuf: 1863 outputbuf: 0 calc elapsed: 1723254 real elapsed: 1723703 (diff: -449) device: 29 delay: 31

Notably, there are neither end of stream or error reading messages in the logs. I'm actually uncertain if this code runs:
https://github.com/ralph-irving/squeezelite/blob/874e4f97d979fbe9b396c1997730a1a2d6797964/stream.c#L407-L410

If the USE_SSL flag is on, doesn't _last_error() always evaluate to ERROR_WOULDBLOCK?
https://github.com/ralph-irving/squeezelite/blob/874e4f97d979fbe9b396c1997730a1a2d6797964/stream.c#L54

I have a visualization to share, but I'll save that for the next post. Thanks, again!

[thickasabrick]

Here's a visualization of the output underrun, the pause, and resume:



I was wondering why this might be Windows-specific. A total shot in the dark, but any chance it has to do with differences with Windows sockets?

Under BSD Unixes, if the remote peer closes its connection and your program is blocking on recv(), you will get a 0 back from recv(). Winsock behaves the same way, except that it can also return -1, with WSAGetLastError() returning WSAECONNRESET, WSAECONNABORTED or WSAESHUTDOWN, to signal the detectable flavors of abnormal disconnections.

From: https://tangentsoft.net/wskfaq/artic...atibility.html

A couple other references:

https://docs.microsoft.com/en-us/windows/win32/winsock/porting-socket-applications-to-winsock

https://docs.microsoft.com/en-us/windows/win32/winsock/return-values-on-function-failure-2

Sorry if that's something you're already aware of. And thank you again!

[ralphy]

Yes, I'd like to track down this issue.

So far, I haven't been able to recreate it locally. I will try your method. Thanks.

Before commenting on your findings, I'd like to take some time to digest them.

I'm in the middle of another lms project ATM so it will take some time before I get to it.

[bwong]

Also running Windows

I am seeing the same problem but my LMS server is running Rocky 8 as a VM under Centos 7. The client is running on Windows 10. I have not been able to track it to the level of detail here which is impressive but I am seeing the same mode of operation.

[bwong]

Problem goes away with squeezelite-1.9.9-1398-ffmpeg-win32

I had been using Squeezelite-X from the Windows store on Windows 10. I just downloaded the latest Squeezelite here:

https://sourceforge.net/projects/lmsclients/files/squeezelite/windows/

It does not have the GUI but I usually use the web interface anyway so starting it in a DOS window is something that gets done when the PC boots. The latest version has no issues.

[ralphy]

I had been using Squeezelite-X from the Windows store on Windows 10. I just downloaded the latest Squeezelite here:

https://sourceforge.net/projects/lmsclients/files/squeezelite/windows/

It does not have the GUI but I usually use the web interface anyway so starting it in a DOS window is something that gets done when the PC boots. The latest version has no issues.

Thanks for confirming. I did make a change in that build to see if it helped.

[ralphy]

I've uploaded new windows builds of squeezelite v1.9.9r1401 which includes a change that should fix the issue.

If you have changed the buffer sizes to workaround the issue using the -b option, please removed it, or change the values back to the default -b 2048:3446 before testing.

There are very few reasons to change the default buffer sizes in squeezelite and in many cases, larger buffers cause playback issues.

Thanks,

[thickasabrick]

Hi, Ralphy! Thank you for looking into this.

I've tested v1.9.9r1401 with the default buffer sizes (no -b option) and have these observations to share:

• playback still stops near the end of a long stream (ex. a 45 minute long podcast)
• playback does not, however, automatically resume after a minute or two — LMS is in "stopped" state
• an STMu (rather than an STMo) is now logged (along with an output underrun message)

Here are some logs, and please let me know if I can be of any further help.

[08:18:52.077] mad_decode:207 end of stream
[08:18:52.078] resample_drain:119 resample track complete - total track clips: 0
[08:18:52.078] process_drain:116 processing track complete - frames in: 109952687 out: 239352788
[08:18:52.078] decode_thread:100 decode complete
[08:18:52.078] sendSTAT:195 STAT: STMd
[08:18:52.078] sendSTAT:195 STAT: STMt
[08:18:53.005] process:528 strm
[08:18:53.005] process_strm:280 strm command t
[08:18:53.005] sendSTAT:195 STAT: STMt
[08:18:54.007] sendSTAT:195 STAT: STMt
[08:18:56.020] sendSTAT:195 STAT: STMt
[08:18:58.012] sendSTAT:195 STAT: STMt
[08:18:58.012] process:528 strm
[08:18:58.012] process_strm:280 strm command t
[08:18:58.012] sendSTAT:195 STAT: STMt
[08:18:59.019] sendSTAT:195 STAT: STMt
[08:19:01.039] slimproto_run:716 output underrun
[08:19:01.039] sendSTAT:195 STAT: STMu
[08:19:03.012] process:528 strm
[08:19:03.012] process_strm:280 strm command t
[08:19:03.012] sendSTAT:195 STAT: STMt

[ralphy]

Hi, Ralphy! Thank you for looking into this.

I've tested v1.9.9r1401 with the default buffer sizes (no -b option) and have these observations to share:

• playback still stops near the end of a long stream (ex. a 45 minute long podcast)
• playback does not, however, automatically resume after a minute or two — LMS is in "stopped" state
• an STMu (rather than an STMo) is now logged (along with an output underrun message)

The issue you describe has been reported by other forum members and happens on hardware players too.
I'm not discounting that there my still be an issue with the windows squeezelite builds, but

The following google search returns at lot of different threads reporting a similiar problem.

site:forums.slimdevices.com podcasts stop

[bpa]

The issue you describe has been reported by other forum members and happens on hardware players too.
I'm not discounting that there my still be an issue with the windows squeezelite builds, but

The following google search returns at lot of different threads reporting a similiar problem.

site:forums.slimdevices.com podcasts stop

Try WebUI Settings/Advanced/Network/Streaming mode for HTTP(s) -> Persistent

[thickasabrick]

Thank you, Ralphy and bpa!

Indeed, there are many threads that describe similar bugs, and I have been using the "Cache HTTP(S) streams on disk" option.

The puzzling thing is that using a very large buffer size (-b 524288) continues to work as a workaround in my case, including with v1.9.9r1401.

Thanks again for your help, and please let me know if I can provide any further information.

[philippe_44]

Music streaming stops intermittently

Resuming that discussion I think we have a final view and fix of the problem which is a general problem, not specific really to us. I'll use an example to describe the problem, although it is not exactly the flow of events for squeezelite

- an mp3 file is 3.5 MB at 160 kbits/s = 20 kB/s
- a client reads it at the exact required speed, 20kB/sec, let's say one recv() of 20kB per second, no pre-buffering for simplicity
- some OS, like Windows, can have very large TCP kernel buffer (about 3MB or more) and with a fast connection, the TCP windows size is widely open
- in a matter of seconds, the whole file is sent to the client, let's say that about 3MB are in the kernel buffers
- as far as the server is concerned, all has been sent and acknowledge, so it does a close()
- the close() sends a FIN to the client which responds by an ACK and the server enters FIN_WAIT_2 state
- BUT, at that point from a client point of view, all recv() will have plenty of read for the next 150 s before it sees the eof!
- so client, will not do a close() and thus will not send a FIN
- the server is in FIN_WAIT_2 state and according to the TCP specs, it should stay like that *forever*
- now, various OS (Windows at least) start a timer similar to TIME_WAIT (120s) when starting a close(), or when receiving the ACK of their FIN, that I don't know (in fact Windows has a specific registry entry for that, see below). This is to more aggressively deal with half-closed sockets.
- of course, after 120s, the server has not seen a client's FIN and sends a RST
- that RST is received by the client and causes an error there and all the remaining data in the TCP buffers to be discarded and lost
- of course, none of that happens with high bitrate formats as the client consumes data fast enough so that the kernel TCP buffers are never idle for 120s and it might not happen for low bit rate when the application buffering system reads it all. It has to be the bad combination of bitrate, file size and kernel's buffers... hence it does not happen all the time.

That's it. That can be reproduced with a few lines of code and every HTTP server. This can be debated, but I see that as a systemic OS issue. Now, the solution is to force client's receive buffers (SO_RCVBUF) to a lower level so that the server has little chances to have sent all data and that data sits in client's kernel buffers for too long. Note that this can still happen though if the buffer is 20kB and the client consumes it at 1B/s... hence I call it a systemic failure instead.

[edit]: the registry key to set FIN_WAIT_2is HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Servic es\Tcpip\Parameters\TcpFinWait2Delay, a DWORD between 30 to 300s

[edit2]: in Windows, the getsockopt of so_rcvbuffer returns 64kB and setting it with that returned value solves the problem. Why? It’s because Windows uses a feature named TCP auto tuning where the buffers are adjusted automatically depending on estimation of BW/latency. Setting so_rcvbuf disables that feature on a per-socket level (I can be done at the system level as well)

[ralphy]

Thank you philippe_44.

I've updated these lmsclient windows builds with the change.

squeezelite 1.9.9-1419
squeezeplay 8.0.1r1420

and

Marco Curti's squeezelite 1.8.4 R2

[thickasabrick]

Amazing sleuthing, Philippe and Ralphy. A very tricky and obscure bug.

I've been using r1419 with the default buffer size (no -b argument) for a week without any issues. Have a Happy New Year!