Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
Amazing sleuthing, Philippe and Ralphy. :cool: 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! thickasabrick's Profile: http://forums.slimdevices.com/member.php?userid=72476 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
Thank you philippe_44. I've updated these lmsclient windows builds with the change. 'squeezelite 1.9.9-1419' (https://sourceforge.net/projects/lmsclients/files/squeezelite/windows/) 'squeezeplay 8.0.1r1420' (https://sourceforge.net/projects/lmsclients/files/squeezeplay/windows/) and 'Marco Curti's squeezelite 1.8.4 R2' (https://sourceforge.net/projects/lmsclients/files/squeezelite/windows/r2/) Ralphy *1*-Touch, *5*-Classics, *3*-Booms, *2*-UE Radio 'Squeezebox client builds' (https://sourceforge.net/projects/lmsclients/files/) 'donations' (https://www.paypal.com/cgi-bin/webscr?cmd=_donations=LL5P6365KQEXN=CA_name=Squeezebox%20client%20builds_code=USD=PP%2dDonationsBF%3abtn_donate_SM%2egif%3aNonHosted) always appreciated. ralphy's Profile: http://forums.slimdevices.com/member.php?userid=3484 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] 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 fats 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 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, AFAIK). This is to more aggressively deal with half-closed sockets. - of course, after 120s, the server has not seen a client's FIN and send a RST - that RST is received by the client and cause and error there and all the remaining data in the TCP buffers to be discarded and lost 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 that seems to work 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. LMS 8.2 on Odroid-C4 - *SqueezeAMP!*, 5xRadio, 5xBoom, 2xDuet, 1xTouch, 1xSB3. Sonos PLAY:3, PLAY:5, Marantz NR1603, Foobar2000, ShairPortW, 2xChromecast Audio, Chromecast v1 and v2, Squeezelite on Pi, Yamaha WX-010, AppleTV 4, Airport Express, GGMM E5, RivaArena 1 & 3 philippe_44's Profile: http://forums.slimdevices.com/member.php?userid=17261 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
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. thickasabrick's Profile: http://forums.slimdevices.com/member.php?userid=72476 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
ralphy wrote: > 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. > > > Code: > > site:forums.slimdevices.com podcasts stop > > Try WebUI Settings/Advanced/Network/Streaming mode for HTTP(s) -> Persistent bpa's Profile: http://forums.slimdevices.com/member.php?userid=1806 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
thickasabrick wrote: > 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. Code: site:forums.slimdevices.com podcasts stop Ralphy *1*-Touch, *5*-Classics, *3*-Booms, *2*-UE Radio 'Squeezebox client builds' (https://sourceforge.net/projects/lmsclients/files/) 'donations' (https://www.paypal.com/cgi-bin/webscr?cmd=_donations=LL5P6365KQEXN=CA_name=Squeezebox%20client%20builds_code=USD=PP%2dDonationsBF%3abtn_donate_SM%2egif%3aNonHosted) always appreciated. ralphy's Profile: http://forums.slimdevices.com/member.php?userid=3484 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
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. Code: [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 thickasabrick's Profile: http://forums.slimdevices.com/member.php?userid=72476 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
I've uploaded new 'windows builds of squeezelite v1.9.9r1401' (https://sourceforge.net/projects/lmsclients/files/squeezelite/windows/) 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, Ralphy *1*-Touch, *5*-Classics, *3*-Booms, *2*-UE Radio 'Squeezebox client builds' (https://sourceforge.net/projects/lmsclients/files/) 'donations' (https://www.paypal.com/cgi-bin/webscr?cmd=_donations=LL5P6365KQEXN=CA_name=Squeezebox%20client%20builds_code=USD=PP%2dDonationsBF%3abtn_donate_SM%2egif%3aNonHosted) always appreciated. ralphy's Profile: http://forums.slimdevices.com/member.php?userid=3484 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
bwong wrote: > 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. I sent a PM to thickasabrick a while ago, but have not heard back. Thanks for confirming. I did make a change in that build to see if it helped. I'll commit the change and create new builds. Ralphy *1*-Touch, *5*-Classics, *3*-Booms, *2*-UE Radio 'Squeezebox client builds' (https://sourceforge.net/projects/lmsclients/files/) 'donations' (https://www.paypal.com/cgi-bin/webscr?cmd=_donations=LL5P6365KQEXN=CA_name=Squeezebox%20client%20builds_code=USD=PP%2dDonationsBF%3abtn_donate_SM%2egif%3aNonHosted) always appreciated. ralphy's Profile: http://forums.slimdevices.com/member.php?userid=3484 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
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. bwong's Profile: http://forums.slimdevices.com/member.php?userid=70367 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
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's Profile: http://forums.slimdevices.com/member.php?userid=70367 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
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. Ralphy *1*-Touch, *5*-Classics, *3*-Booms, *2*-UE Radio 'Squeezebox client builds' (https://sourceforge.net/projects/lmsclients/files/) 'donations' (https://www.paypal.com/cgi-bin/webscr?cmd=_donations=LL5P6365KQEXN=CA_name=Squeezebox%20client%20builds_code=USD=PP%2dDonationsBF%3abtn_donate_SM%2egif%3aNonHosted) always appreciated. ralphy's Profile: http://forums.slimdevices.com/member.php?userid=3484 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
Here's a visualization of the output underrun, the pause, and resume: 36848 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/articles/bsd-compatibility.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! +---+ |Filename: 2022-01-15_squeezelite-playback-interruption-visualization.png| |Download: http://forums.slimdevices.com/attachment.php?attachmentid=36848| +---+ thickasabrick's Profile: http://forums.slimdevices.com/member.php?userid=72476 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
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: Code: [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: Code: [15:56:36.037] stream_thread:428 streambuf read 1800 bytes streambuf is entirely full: Code: [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: Code: [15:56:49.477] decode_thread:75 streambuf bytes: 129663 outputbuf space: 684959 1863 bytes seem to be stuck in the streambuf, however: Code: [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: Code: [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: Code: [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's Profile: http://forums.slimdevices.com/member.php?userid=72476 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
Ralphy, thanks so much for looking into this. The good news is that your change did take effect, and client machine now initiates TCP Keep-Alive packets every 30 secs after last transmission from the server (frames 22775 and 23007 in Wireshark trace below). The bad news is that Linux TCP stack does not seem to care about that. My guess is that once Linux starts the TCP FIN timeout timer after FIN packet is sent out it does not reset it, even if Keep-Alive packet is received. 34931 +---+ |Filename: tcp_session_rst_02_v1389.png | |Download: http://forums.slimdevices.com/attachment.php?attachmentid=34931| +---+ lngxa's Profile: http://forums.slimdevices.com/member.php?userid=71826 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
Thanks for taking the time to research what's happening. Sorry, it's taken so long for me to reply. There is a lot of information to digest and I wanted to take the time to review it all. One thought I had was if enabling tcp keep alive would prevent the server closing the socket. I've sent you a PM with a test windows squeezelite build that enables 30 second tcp keep alives on the streaming socket. It's 32bit since my 64bit build laptop is waiting for a replacement power adapter to arrive. You should see this in the squeezelite debug log. Code: [13:52:01.701] set_keepalive:294 tcp keepalive enabled and I've included a patch file in the zip with the code change. Ralphy *1*-Touch, *5*-Classics, *3*-Booms, *2*-UE Radio 'Squeezebox client builds' (https://sourceforge.net/projects/lmsclients/files/) 'donations' (https://www.paypal.com/cgi-bin/webscr?cmd=_donations=LL5P6365KQEXN=CA_name=Squeezebox%20client%20builds_code=USD=PP%2dDonationsBF%3abtn_donate_SM%2egif%3aNonHosted) always appreciated. ralphy's Profile: http://forums.slimdevices.com/member.php?userid=3484 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
Last thing I was curious about is why only Windows users are seemingly experiencing this issue. Logically thinking, the underlying condition should be happening on Linux just the same. I ran a test on Linux to find out. 34918 As we can see, TCP flow timing on Linux looks very similar to Windows. Server sends TCP FIN packet and client takes another 150 seconds to drain TCP receive buffer and reply with FIN, ACK. Server then responds with RST instead of final ACK, because socket on the server has already been destroyed. The only difference here is that Linux does not send TCP Window Update packets to the server as the buffer is drained, so it does not trigger RST from the server before client has time to read all the data from the buffer. +---+ |Filename: tcp_session_linux.jpg| |Download: http://forums.slimdevices.com/attachment.php?attachmentid=34918| +---+ lngxa's Profile: http://forums.slimdevices.com/member.php?userid=71826 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
We have a lot of different variables at play here: song size, song bitrate, LMS, squeezelite, squeezelite stream buffer, server TCP send buffer, client TCP receive buffer, server TCP FIN timeout. Lets briefly look into what each of these contribute. Song size and song bitrate - we don't have any control over these, but they obviously play big role in this failure. Song needs to be big enough to fill all the buffers and bitrate needs to be low enough to slow down how fast buffers are drained. Most of the songs do not meet requirements to trigger this issue though. LMS is not really doing anything wrong, it sends the data out as fast as it can and once all of the data is written to the socket it closes it. squeezelite is also not at fault here, it is reading data as fast as it can and suddenly socket disappears on it. I ran this same test with squeezeplay and failure mode was exactly the same. Squeezeplay uses larger buffer size 3145728 (vs 2097152) so everything failed closer to the end of the song. TCP send buffer - the size of this buffer does not really matter, because kernel TCP stack sends TCP FIN packet to the client only after this buffer is emptied. squeezelite stream buffer - this can be increased and it will reduce how often this issue happens, but it will not eliminate the issue. You can always find file that will be larger than the buffer size. TCP receive buffer and TCP FIN timeout - the combination of these is what causes the issue. If the TCP receive buffer is larger than the TCP FIN timeout multiplied by the song bitrate, we are going to have a failure. To test this I have increased TCP FIN timeout (net.ipv4.tcp_fin_timeout) on the server from 60 sec to 120 sec and that of course allowed enough time for the client to finish reading data from the TCP buffers. Client finished reading data 84 seconds after server finished sending data. 34910 What are some of the possible solutions? Haven't given much thought to these, so some might not make sense. Increasing squeezelite stream buffer - that's what most of the people that experience this issue are doing now. Increasing TCP FIN timeout (net.ipv4.tcp_fin_timeout) on the server - it is a system wide setting and might not be a good idea if LMS is not running on the dedicated box. LMS setting FIN time out on the socket level using SO_LINGER - not sure if this is possible though. Squeezelite explicitly setting TCP receive buffer size on the socket level using SO_RCVBUF - is this possible. LMS waiting to close the socket until Squeezelite notifies it that all of the data was received - this would be the only way to cover 100% of the cases, but is this possible to do? Thanks for reading and sorry for the long posts! +---+ |Filename: tcp_session_ok_large_fin_timeout.jpg | |Download: http://forums.slimdevices.com/attachment.php?attachmentid=34910| +---+ lngxa's Profile: http://forums.slimdevices.com/member.php?userid=71826 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
Now lets look at the squeezelite logs: Code: [01:16:08.861] stream_thread:428 streambuf read 3132 bytes [01:16:08.961] stream_thread:428 streambuf read 1566 bytes [01:16:09.026] sendSTAT:166 ms_played: 328110 (frames_played: 14470092 device_frames: 441) [01:16:09.026] sendSTAT:195 STAT: STMt [01:16:09.026] sendSTAT:200 received bytesL: 12661166 streambuf: 2093499 outputbuf: 3325264 calc elapsed: 328110 real elapsed: 328203 (diff: -93) device: 10 delay: 0<-- first STMt after LMS closed connection [01:16:09.026] process:528 strm [01:16:09.026] process_strm:280 strm command t [01:16:09.026] sendSTAT:166 ms_played: 328110 (frames_played: 14470092 device_frames: 441) [01:16:09.026] sendSTAT:195 STAT: STMt [01:16:09.026] sendSTAT:200 received bytesL: 12661166 streambuf: 2093499 outputbuf: 3325264 calc elapsed: 328110 real elapsed: 328203 (diff: -93) device: 10 delay: 0 [01:16:09.062] stream_thread:428 streambuf read 3652 bytes ... reading from the buffer continues [01:18:31.890] stream_thread:428 streambuf read 3340 bytes <-- frame 17677 with TCP FIN arrives [01:18:31.991] stream_thread:428 streambuf read 3131 bytes [01:18:32.021] process:528 strm [01:18:32.021] process_strm:280 strm command t [01:18:32.021] sendSTAT:166 ms_played: 471080 (frames_played: 20775069 device_frames: 441) [01:18:32.021] sendSTAT:195 STAT: STMt [01:18:32.021] sendSTAT:200 received bytesL: 16819726 streambuf: 2097151 outputbuf: 3306184 calc elapsed: 471080 real elapsed: 471203 (diff: -123) device: 10 delay: 0 [01:18:32.092] stream_thread:428 streambuf read 3445 bytes [01:18:32.193] stream_thread:428 streambuf read 1253 bytes ... reading from the buffer continues [01:19:40.919] stream_thread:428 streambuf read 4280 bytes [01:19:41.019] stream_thread:428 streambuf read 3236 bytes [01:19:41.021] sendSTAT:166 ms_played: 540080 (frames_played: 23817969 device_frames: 441) [01:19:41.021] sendSTAT:195 STAT: STMt [01:19:41.021] sendSTAT:200 received bytesL: 18902856 streambuf: 2097151 outputbuf: 3320872 calc elapsed: 540080 real elapsed: 540203 (diff: -123) device: 10 delay: 0 [01:19:41.120] stream_thread:428 streambuf read 2296 bytes [01:19:41.220] stream_thread:428 streambuf read 3654 bytes [01:19:41.321] stream_thread:428 streambuf read 2818 bytes [01:19:41.422] stream_thread:428 streambuf read 3237 bytes [01:19:41.522] stream_thread:428 streambuf read 3445 bytes <-- last read from the stream buffer [01:19:43.021] sendSTAT:166 ms_played: 542080 (frames_played: 23906169 device_frames: 441) [01:19:43.021] sendSTAT:195 STAT: STMt [01:19:43.021] sendSTAT:200 received bytesL: 18918306 streambuf: 2049237 outputbuf: 3334120 calc elapsed: 542080 real elapsed: 542203 (diff: -123) device: 10 delay: 0 [01:19:44.019] process:528 strm [01:19:44.019] process_strm:280 strm command t [01:19:44.019] sendSTAT:166 ms_played: 543080 (frames_played: 23950269 device_frames: 441) [01:19:44.019] sendSTAT:195 STAT: STMt [01:19:44.019] sendSTAT:200 received bytesL: 18918306 streambuf: 2020947 outputbuf: 3322312 calc elapsed: 543080 real elapsed: 543203 (diff: -123) device: 10 delay: 0 [01:19:45.020] sendSTAT:166 ms_played: 544080 (frames_played: 23994369 device_frames: 441) [01:19:45.020] sendSTAT:195 STAT: STMt [01:19:45.020] sendSTAT:200 received bytesL: 18918306 streambuf: 1994641 outputbuf: 3301288 calc elapsed: 544080 real elapsed: 544203 (diff: -123) device: 10 delay: 0 [01:19:47.021] sendSTAT:166 ms_played: 546096 (frames_played: 24082569 device_frames: 441) [01:19:47.021] sendSTAT:195 STAT: STMt [01:19:47.021] sendSTAT:200 received bytesL: 18918306 streambuf: 1940677 outputbuf: 3314536 calc elapsed: 546096 real elapsed: 546203 (diff: -107) device: 10 delay: 16 ... [01:20:59.017] sendSTAT:200 received bytesL: 18918306 streambuf: 2019 outputbuf: 209176 calc elapsed: 618036 real elapsed: 618203 (diff: -167) device: 10 delay: 16 [01:21:00.018] sendSTAT:166 ms_played: 618638 (frames_played: 27281711 device_frames: 441) [01:21:00.018] sendSTAT:195 STAT: STMo [01:21:00.018] sendSTAT:200 received bytesL: 18918306 streambuf: 2019 outputbuf: 0 calc elapsed: 618638 real elapsed: 619203 (diff: -565) device: 10 delay: 16 [01:21:00.018] process:528 strm [01:21:00.018] process_strm:280 strm command t [01:21:00.018] sendSTAT:166 ms_played: 618638 (frames_played: 27281711 device_frames: 441) [01:21:00.018] sendSTAT:195 STAT: STMt [01:21:00.018] sendSTAT:200 received bytesL: 18918306 streambuf: 2019 outputbuf: 0 calc elapsed: 618638 real elapsed: 619203 (diff: -565) device: 10 delay: 16 [01:21:00.028] process:528 strm [01:21:00.028] process_strm:280 strm command p [01:21:00.028] sendSTAT:166 ms_played: 618654 (frames_played: 27281711 device_frames: 441) [01:21:00.028] sendSTAT:195 STAT: STMp [01:21:00.028]
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
After the pause LMS starts streaming again, then pauses once buffers fill up. Code: [21-06-01 01:11:41.5583] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun... <-- streaming resumes after the second pause [21-06-01 01:11:41.5589] Slim::Web::HTTP::sendStreamingResponse (2276) (audio: 32768 bytes) [21-06-01 01:11:41.5592] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 32768 to 192.168.10.100 ... [21-06-01 01:11:41.6963] Slim::Web::HTTP::sendStreamingResponse (2276) (audio: 32768 bytes) [21-06-01 01:11:41.6965] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 32768 to 192.168.10.100 <-- streaming pauses for the third time ... [21-06-01 01:11:42.0045] Slim::Networking::Slimproto::_stat_handler (778) FACTORYTEST event=stat mac=00:02:c9:13:08:d0 signalstrength=65535 [21-06-01 01:11:42.0047] Slim::Networking::Slimproto::_stat_handler (784) 00:02:c9:13:08:d0: STAT-STMt: fullness=2093497, output_fullness=3330736, elapsed=59.206 [21-06-01 01:11:42.0049] Slim::Networking::Slimproto::_stat_handler (811) 00:02:c9:13:08:d0 Squeezebox stream status: event_code: STMt bytes_rec_H 0 bytes_rec_L 4216443 fullness:2093497 (99%) bufferSize 2097152 fullness 2093497 bytes_received 4216443 signal_strength: 65535 jiffies: 1655225250 voltage: 0 [21-06-01 01:11:42.0050] Slim::Networking::Slimproto::_stat_handler (823) output size: 3528000 output fullness: 3330736 elapsed seconds: 59 [21-06-01 01:11:42.0052] Slim::Networking::Slimproto::_stat_handler (835) elapsed milliseconds: 59206 server timestamp: 0 This stream/pause repeats for a bit. We have a total of 6 pauses and 7 streaming bursts. I am not going to posts logs for all that since there is really nothing interesting happening. Here is a table that summarizes how much data was sent and received in each burst. Code: Bytes sent in this burst | Bytes sent Total | Bytes Received | Difference in bytes and playback time 1st burst: 599703559970352393886 3603149 118 seconds 2nd burst: 311296091099952448379 6661616 218 seconds 3rd burst: 212992011239915 4216443 7023472 230 seconds 4th burst: 209715213337067 6373697 6963370 228 seconds 5th burst: 209715215434219 8421048 7013171 229 seconds 6th burst: 209715217531371 10549011 6982360 228 seconds 7th burst: 182372319355094 12661166 6693928 219 seconds As you can see we steadily have around 220-230 seconds worth of playback time sitting in TCP buffers. Lets skip to LMS ending the stream: Code: [21-06-01 01:16:09.2640] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun... [21-06-01 01:16:09.2643] Slim::Web::HTTP::sendStreamingResponse (2276) (audio: 21483 bytes) [21-06-01 01:16:09.2646] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 21483 to 192.168.10.100 <-- last data streamed [21-06-01 01:16:09.2648] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun... [21-06-01 01:16:09.2651] Slim::Player::Protocols::File::sysread (283) Trying to read past the end of file: file:///mnt/media/music/popular/Led.Zeppelin/In.Through.the.Out.Door.(1979)/05%20-%20Led%20Zeppelin%20-%20Carouselambra.mp3 [21-06-01 01:16:09.2653] Slim::Player::Source::_readNextChunk (349) Read to end of file or pipe [21-06-01 01:16:09.2656] Slim::Player::Source::_readNextChunk (372) end of file or error on socket, song pos: 19390336, tell says: 19390336, totalbytes: 19354603 [21-06-01 01:16:09.2658] Slim::Player::Source::_readNextChunk (377) 00:02:c9:13:08:d0 mark end of stream [21-06-01 01:16:09.2675] Slim::Player::StreamingController::_eventAction (272) 00:02:c9:13:08:d0: LocalEndOfStream in PLAYING-STREAMING -> Slim::Player::StreamingController::_Streamout [21-06-01 01:16:09.2678] Slim::Player::StreamingController::_setStreamingState (2386) new streaming state STREAMOUT [21-06-01 01:16:09.2680] Slim::Player::StreamingController::_eventAction (302) 00:02:c9:13:08:d0: LocalEndOfStream - new state PLAYING-STREAMOUT [21-06-01 01:16:09.2683] Slim::Web::HTTP::sendStreamingResponse (2299) Nothing to stream, let's wait for 0.4 seconds... [21-06-01 01:16:09.2688] Slim::Web::HTTP::sendStreamingResponse (2412) $httpClient is: Slim::Web::HTTP::ClientConn=GLOB(0x5615ba8704c0)
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
LMS continues sending data to squeezelite non stop until buffers fill up and then it pauses. Code: [21-06-01 01:10:42.7389] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun... [21-06-01 01:10:42.7390] Slim::Web::HTTP::sendStreamingResponse (2276) (audio: 32768 bytes) [21-06-01 01:10:42.7391] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 32768 to 192.168.10.100 <-- last data sent before pause [21-06-01 01:10:42.7803] Slim::Networking::Slimproto::client_readable (393) Slimproto frame: STAT, len: 53 [21-06-01 01:10:42.7808] Slim::Player::Player::trackJiffiesEpoch (925) 00:02:c9:13:08:d0 trackJiffiesEpoch: epoch=1620872676.75235, offset=1620872676.74956 [21-06-01 01:10:42.7810] Slim::Player::Player::trackJiffiesEpoch (932) 00:02:c9:13:08:d0 adjust jiffies epoch -0.003s [21-06-01 01:10:42.7813] Slim::Networking::Slimproto::_stat_handler (778) FACTORYTEST event=stat mac=00:02:c9:13:08:d0 signalstrength=65535 [21-06-01 01:10:42.7815] Slim::Networking::Slimproto::_stat_handler (784) 00:02:c9:13:08:d0: STAT-STMs: fullness=2097151, output_fullness=3345784, elapsed=0.000 [21-06-01 01:10:42.7817] Slim::Networking::Slimproto::_stat_handler (811) 00:02:c9:13:08:d0 Squeezebox stream status: event_code: STMs bytes_rec_H 0 bytes_rec_L 2393886 fullness:2097151 (99%) bufferSize 2097152 fullness 2097151 bytes_received 2393886 signal_strength: 65535 jiffies: 1655166031 voltage: 0 [21-06-01 01:10:42.7819] Slim::Networking::Slimproto::_stat_handler (823) output size: 3528000 output fullness: 3345784 elapsed seconds: 0 [21-06-01 01:10:42.7821] Slim::Networking::Slimproto::_stat_handler (835) elapsed milliseconds: 0 server timestamp: 0 [21-06-01 01:10:42.7824] Slim::Player::StreamingController::playerTrackStarted (2200) 00:02:c9:13:08:d0 [21-06-01 01:10:42.7826] Slim::Player::StreamingController::_eventAction (272) 00:02:c9:13:08:d0: Started in BUFFERING-STREAMING -> Slim::Player::StreamingController::_Playing [21-06-01 01:10:42.7829] Slim::Player::StreamingController::_setPlayingState (2377) new playing state PLAYING [21-06-01 01:10:42.7831] Slim::Player::StreamingController::_Playing (368) Song 0 has now started playing LMS does not log how much total data it streamed, but it logs every socket write, so I added everything up and at this point in time LMS has already sent out 5997035 bytes (5.71 MB) of data, but squeezelite reports that it has only received 2393886 bytes (2.28 MB). 5997035 minus 2393886 = 3603149 bytes (3.43 MB). So now we know that 3.43 MB of data is sitting in TCP send buffers on the LMS server machine and TCP receive buffers on the squeezelite client machine. Song I am playing is 244 kbps which means we have 118 seconds of song sitting in TCP buffers Since squeezelite stream buffer is full at this point it would take squeezelite 118 seconds to retrieve everything from TCP buffers. Code: [01:10:40.702] stream_thread:428 streambuf read 7300 bytes [01:10:40.702] stream_thread:428 streambuf read 13787 bytes [01:10:40.702] pa_monitor:294 device reopen [01:10:40.702] pa_monitor:304 end monitor thread [01:10:40.702] _pa_open:409 opened device 6 - Topping E30 (2- TOPPING USB DAC) [Windows WASAPI] at 44100 latency 21 ms [01:10:40.749] _check_lame_header:163 gapless: skip: 2257 samples: 27974100 delay: 1105 padding: 1115 [01:10:40.811] stream_thread:428 streambuf read 1 bytes [01:10:40.811] stream_thread:428 streambuf read 296734 bytes [01:10:40.811] pa_callback:525 pad with silence [01:10:40.811] sendSTAT:171 ms_played: 0 [01:10:40.811] sendSTAT:195 STAT: STMs [01:10:40.811] sendSTAT:200 received bytesL: 2393886 streambuf: 2097151 outputbuf: 3345784 calc elapsed: 0 real elapsed: 0 (diff: 0) device: 10 delay: 0 [01:10:40.811] sendSTAT:171 ms_played: 0 [01:10:40.811] sendSTAT:195 STAT: STMt [01:10:40.811] sendSTAT:200 received bytesL: 2393886 streambuf: 2097151 outputbuf: 3345784 calc elapsed: 0 real elapsed: 0 (diff: 0) device: 10 delay: 0 [01:10:41.012] stream_thread:428 streambuf read 3131 bytes [01:10:41.113] stream_thread:428 streambuf read 3237 bytes This is how TCP flow looks. Note that this pause is very short, so no keep-alive packets were sent out. 34903 LMS resumes streaming and then pauses again Code: [21-06-01 01:10:42.7923] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun... [21-06-01 01:10:42.7926] Slim::Web::HTTP::sendStreamingResponse (2276) (audio: 32768 bytes) [21-06-01 01:10:42.7929] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 32768 to 192.168.10.100 [21-06-01 01:10:42.7932]
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
I figured the best way to explain the failure mode I am experiencing is to combine/correlate data from LMS logs, squeezelite logs and network traffic capture. Please note that Wireshark is running on the client machine so Wireshark and squeezelite timestamps match, time on LMS machine is ~2 secs ahead. squeezelite startup and buffer sizes: Code: D:\squeezelite-x64.exe -n Callisto -s lms.network.lan -C 60 -o Topping E30 (2- TOPPING USB DAC) [Windows WASAPI] -m 00:02:c9:13:08:d0 -M Squeezelite-X -d all=sdebug -f squeezelite.log [01:10:28.996] stream_init:454 init stream [01:10:28.996] stream_init:455 streambuf size: 2097152 [01:10:28.996] output_init_pa:573 init output [01:10:28.996] output_init_pa:593 requested latency: 0 [01:10:29.043] output_init_common:360 outputbuf size: 3528000 [01:10:29.043] output_init_common:384 idle timeout: 6 [01:10:29.090] output_init_common:432 supported rates: 44100 strm command s, STMc and start of data flow. Everything appears to be working fine here. Code: [01:10:40.529] process:528 strm [01:10:40.529] process_strm:280 strm command s [01:10:40.529] process_strm:350 strm s autostart: 1 transition period: 10 transition type: 0 codec: m [01:10:40.529] sendSTAT:171 ms_played: 0 [01:10:40.529] sendSTAT:195 STAT: STMf [01:10:40.529] sendSTAT:200 received bytesL: 0 streambuf: 0 outputbuf: 0 calc elapsed: 0 real elapsed: 1655165750 (diff: -1655165750) device: 0 delay: 1655165750 [01:10:40.529] codec_open:264 codec open: 'm' [01:10:40.529] connect_socket:164 connecting to 192.168.10.17:9000 [01:10:40.544] stream_sock:600 header: GET /stream.mp3?player=00:02:c9:13:08:d0 HTTP/1.0 [01:10:40.544] sendSTAT:171 ms_played: 0 [01:10:40.544] sendSTAT:195 STAT: STMc [01:10:40.544] sendSTAT:200 received bytesL: 0 streambuf: 0 outputbuf: 0 calc elapsed: 0 real elapsed: 1655165765 (diff: -1655165765) device: 0 delay: 1655165765 [01:10:40.544] process_strm:384 set fade mode: 0, channels: 0, invert: 0 [01:10:40.544] process:528 audg [01:10:40.544] process_audg:440 audg gainL: 37120 gainR: 37120 adjust: 1 [01:10:40.544] set_volume:111 setting internal gain left: 37120 right: 37120 [01:10:40.638] send_header:131 wrote 53 bytes to socket [01:10:40.638] send_header:135 wrote header [01:10:40.638] stream_thread:331 headers: len: 491 HTTP/1.1 200 OK Server: Logitech Media Server (8.1.1 - 1610364019) Connection: close Content-Type: audio/mpeg Set-Cookie: Squeezebox-albumView=; path=/ Set-Cookie: Squeezebox-expandPlayerControl=true; path=/ Set-Cookie: Squeezebox-expanded-MY_MUSIC=1; path=/ Set-Cookie: Squeezebox-expanded-FAVORITES=1; path=/ Set-Cookie: Squeezebox-expanded-PLUGINS=1; path=/ Set-Cookie: Squeezebox-expanded-PLUGIN_MY_APPS_MODULE_NAME=1; path=/ Set-Cookie: Squeezebox-expanded-RADIO=1; path=/ [01:10:40.638] sendRESP:226 RESP [01:10:40.638] stream_thread:428 streambuf read 7300 bytes -<-- first data arriving- [01:10:40.638] stream_thread:428 streambuf read 5840 bytes Code: [21-06-01 01:10:42.4957] Slim::Player::StreamingController::_Stream (1213) 00:02:c9:13:08:d0: preparing to stream song index 0 [21-06-01 01:10:42.4959] Slim::Player::Song::open (360) file:///mnt/media/music/popular/Led.Zeppelin/In.Through.the.Out.Door.(1979)/05%20-%20Led%20Zeppelin%20-%20Carouselambra.mp3 [21-06-01 01:10:42.4963] Slim::Player::TranscodingHelper::enabledFormat (231) Checking to see if mp3-mp3-*-* is enabled [21-06-01 01:10:42.4965] Slim::Player::TranscodingHelper::checkBin (264) Checking formats for: mp3-mp3-*-* [21-06-01 01:10:42.4966] Slim::Player::TranscodingHelper::enabledFormat (231) Checking to see if mp3-mp3-*-* is enabled [21-06-01 01:10:42.4967] Slim::Player::TranscodingHelper::checkBin (272) enabled [21-06-01 01:10:42.4969] Slim::Player::TranscodingHelper::checkBin (274) Found command: - [21-06-01 01:10:42.4971] Slim::Player::TranscodingHelper::getConvertCommand2 (488) Matched: mp3->mp3 via: - [21-06-01 01:10:42.4972] Slim::Player::Song::open (384) seek=false time=0 canSeek=1 [21-06-01 01:10:42.4975] Slim::Player::TranscodingHelper::enabledFormat (231) Checking to see if mp3-mp3-*-* is enabled [21-06-01 01:10:42.4977] Slim::Player::TranscodingHelper::checkBin (264) Checking formats for: mp3-mp3-*-* [21-06-01 01:10:42.4978] Slim::Player::TranscodingHelper::enabledFormat (231) Checking to see if mp3-mp3-*-* is enabled [21-06-01 01:10:42.4979] Slim::Player::TranscodingHelper::checkBin (272) enabled [21-06-01 01:10:42.4980] Slim::Player::TranscodingHelper::checkBin (274) Found command: - [21-06-01 01:10:42.4982] Slim::Player::TranscodingHelper::getConvertCommand2 (488) Matched: mp3->mp3 via: - [21-06-01 01:10:42.4983] Slim::Player::Song::open (414) Transcoder: streamMode=I, streamformat=mp3
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
Thanks for your response guys, I did some more testing and I have a pretty good idea of what is actually happening, but don't have time to post all the details right now, maybe tomorrow. Just to quickly answer your questions. bpa wrote: > > You have virtualised system - can you give more detaisl (e.g. Ubuntu > virtualised under Windows ?) I am running LMS on Ubuntu 20.04.2 LTS server virtualized on ESXi v7, I am pretty sure virtualization does not have anything to do with this issue though. bpa wrote: > > The FIN/RST issue can come about from packets not arriving. Years ago > one cause of this was a Windows security s/w inserted into network chain > and then holding onto last packet for "examination" > > You seem to have suqeezelite , wireshark and LMS logs. Can you see if a > packet goes missing - probably LMS to Client ? > I am running Wireshark on the client side, so screenshots that I posted are showing what's arriving, but I did run Wireshark on the server as well and packets do match up. RST packet is indeed coming from the server, not necessarily LMS itself, most likely kernel TCP stack. ralphy wrote: > There have been 'similiar discussions in the squeezelite thread' > (https://forums.slimdevices.com/showthread.php?97046-Announce-Squeezelite-a-small-headless-squeezeplay-emulator-for-linux-(alsa-only)=981302=1#post981302). > > The discussion goes on for many pages and I have not been able to > reproduce the problem, but several users have reported the issue. > > Do you also get socket errors in the squeezelite logs? Thanks for posting the link, I have not seen it, but will look at it later. No socket errors in the logs. The issue that I am having I think is the same as was discussed in this thread https://forums.slimdevices.com/showthread.php?113554-SqueezeLite-on-Windows-pausing-interruption-dropout-of-audio-every-5-minutes. I don't have an older version of squeezelite to test, but I suspect older version did not handle the condition of socket disappearing (RST packet arriving and Windows destroying TCP receive buffers) very well and thus people were seeing 100% CPU usage and error messages in the log. Handling of that condition was addressed, but the underlying cause of the issue was not. People simply worked around it by increasing buffer size. lngxa's Profile: http://forums.slimdevices.com/member.php?userid=71826 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
There have been 'similiar discussions in the squeezelite thread' (https://forums.slimdevices.com/showthread.php?97046-Announce-Squeezelite-a-small-headless-squeezeplay-emulator-for-linux-(alsa-only)=981302=1#post981302). The discussion goes on for many pages and I have not been able to reproduce the problem, but several users have reported the issue. Do you also get socket errors in the squeezelite logs? Ralphy *1*-Touch, *5*-Classics, *3*-Booms, *2*-UE Radio 'Squeezebox client builds' (https://sourceforge.net/projects/lmsclients/files/) 'donations' (https://www.paypal.com/cgi-bin/webscr?cmd=_donations=LL5P6365KQEXN=CA_name=Squeezebox%20client%20builds_code=USD=PP%2dDonationsBF%3abtn_donate_SM%2egif%3aNonHosted) always appreciated. ralphy's Profile: http://forums.slimdevices.com/member.php?userid=3484 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
lngxa wrote: > Few other musings: > > > > > - this issue does not happen when playing flac most likely because > it is higher bitrate so it drains output buffer quicker - easiest way to reproduce this is probably to use long mp3 file > with low bitrate - there are few other reports of a similar issue in this forum; > people have fixed it by increasing squeezelite stream buffer size > using -b parameter > > > > > I have skimmed the above posts but since other users do not have your problem, I would start looking at what is different on yoursystem - You have virtualised system - can you give more detaisl (e.g. Ubuntu virtualised under Windows ?) The FIN/RST issue can come about from packets not arriving. Years ago one cause of this was a Windows security s/w inserted into network chain and then holding onto last packet for "examination" You seem to have suqeezelite , wireshark and LMS logs. Can you see if a packet goes missing - probably LMS to Client ? > How does LMS manage data transmission rate? Is the rate controlled by > LMS or client? Client "controlled". Client issues a http/GET - LMS pushes the data out as fast as it can so if when client buffer fills, TCP windows will stop advancing and so LMS will not be able to send any more data until it is allowed but it'll try. The GET is on a separate TCP connection from slimproto communications. After initiating playback, client will put data into buffer until it reaches a threshold and then it starts playing. For small files, usually LMS will continue sending data to client and so client will end up buffering whole file while playing. For large files, LMS will fill internal buffer, playback will continue, as buffer is emptied client will request more data from LMS to kepp buffer topped up. IIRC Underrun is sent when decoded buffer is empty. LMS logs of slimproto can be enable to show state of internal buffer as reported by client. If you alter client buffer sizes (there are two: receive and decoded) - you may be able to characterise the problem a bit better. bpa's Profile: http://forums.slimdevices.com/member.php?userid=1806 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
Few other musings: - this issue does not happen when playing flac most likely because it is higher bitrate so it drains output buffer quicker - easiest way to reproduce this is probably to use long mp3 file with low bitrate - there are few other reports of a similar issue in this forum; people have fixed it by increasing squeezelite stream buffer size using -b parameter How does LMS manage data transmission rate? Is the rate controlled by LMS or client? lngxa's Profile: http://forums.slimdevices.com/member.php?userid=71826 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
Looked a little bit deeper into this issue. First I thought this might be the same issue as described in this thread https://forums.slimdevices.com/showthread.php?113554-SqueezeLite-on-Windows-pausing-interruption-dropout-of-audio-every-5-minutes, but now I am not so sure about that. Here are couple notes: - server and client are both on the same subnet and are hardwired, so we are not dealing with wifi issues - issue happens when streaming mp3 files, does not happen on every file I stream - so far I have not experienced this issue while streaming flac files With this in mind I have two test cases that I am using now to consistently reproduce this issue: - playing 17min long flac file (545 kbps bitrate), single file in the play queue - this always works fine - playing 10.5min mp3 file (244 kbps bitrate), single file in the play queue - this always stops I ran Wireshark on the client machine to see what is happening on the wire in those two cases and we can see a clear difference. When playing flac, TCP connection is created, server periodically streams data to the client and keeps session open during periods of inactivity with TCP Keep-Alive packets. Below picture shows what happens when stream closes. As you can see everything looks fine, TCP session is correctly terminated (server sends FIN, client replies with FIN, ACK and server sends final ACK). Server indicates 69787849 bytes streamed which is the exact size of the flac file, so we know server sent all of the data to the client. 34880 squeezelite logs also indicate that it received 69787849 bytes Code: [12:10:50.075] stream_thread:428 streambuf read 8192 bytes [12:10:50.176] stream_thread:428 streambuf read 210 bytes [12:10:50.176] STREAM_THREAD:404 END OF STREAM (69787849 BYTES) [12:10:50.176] sendDSCO:214 DSCO: 0 [12:10:51.176] sendSTAT:166 ms_played: 967620 (frames_played: 42672483 device_frames: 441) [12:10:51.176] sendSTAT:195 STAT: STMt [12:10:51.176] sendSTAT:200 received bytesL: 69787849 streambuf: 2040017 outputbuf: 3335968 calc elapsed: 967620 real elapsed: 968094 (diff: -474) device: 10 delay: 0 [12:10:51.637] process:528 strm When playing mp3 file, TCP connection is also kept alive with TCP Keep-Alive packets during periods of inactivity, but things change once we reach the end of the stream. Server initiates TCP FIN sequence and indicates transmission of 19354603 bytes. Actual mp3 file is 19390464 bytes, but server log indicates 19354603 as total bytes, so this is probably taking into account removal of trailing/leading silence from the file. I think we can assume that server did send out all of the audio bytes. Code: [21-06-01 01:16:09.2656] Slim::Player::Source::_readNextChunk (372) end of file or error on socket, song pos: 19390336, tell says: 19390336, totalbytes: *19354603* Client acknowledges receipt of all data packets up to frame 17677, but then it takes 70 seconds for the client to send TCP Window Update packet. As you can see from the working example above, client sends two TCP Window Update packets and the follows up with TCP FIN. But in this case server replies with TCP RST (reset) and game is over. 34881 Why did server reply with TCP RST? I think this has to do with Linux TCP IPv4 settings, in particular net.ipv4.tcp_fin_timeout, which on my server is set to 60 seconds. Per IBM documentation: -This parameter determines the length of time an orphaned (unreferenced) connection will wait before it is aborted at the local end. This parameter is especially helpful for when something happens to the remote peer which prevents or excessively delays a response-. Basically server sent out TCP FIN and because it did not receive FIN, ACK from the client in 60 seconds, connection was automatically destroyed. Once client sent a packet 70 seconds after receiving FIN from the server, server replied with RST because that TCP connection no longer exists. Did squeezelite received all 19354603 bytes of data that server sent? Code: [01:19:41.321] stream_thread:428 streambuf read 2818 bytes [01:19:41.422] stream_thread:428 streambuf read 3237 bytes [01:19:41.522] stream_thread:428 streambuf read *3445 *bytes <-- last buffer read [01:19:43.021] sendSTAT:166 ms_played: 542080 (frames_played: 23906169 device_frames: 441) [01:19:43.021] sendSTAT:195 STAT: STMt [01:19:43.021] sendSTAT:200 *received bytesL: 18918306* streambuf: 2049237 outputbuf: 3334120 calc elapsed: 542080 real elapsed: 542203 (diff: -123) device: 10 delay: 0 [01:19:44.019] process:528 strm [01:19:44.019] process_strm:280 strm command t Log indicates that it only received 18918306 bytes of data. It also does not log "end of stream" message as seen in the working example. At this point
Re: [SlimDevices: SqueezeCenter] Music streaming stops intermittently
I am attaching LMS log, but here are some pointers to locations in the log STMo received Code: [21-05-31 01:11:50.0069] Slim::Networking::Slimproto::_stat_handler (784) 00:02:c9:aa:bb:cc: STAT-STMo: fullness=1952, output_fullness=-1, elapsed=164.249 music starts playing again Code: [21-05-31 01:12:21.1553] Slim::Player::StreamingController::jumpToTime (2166) 00:02:c9:aa:bb:cc +---+ |Filename: server_03_single_song_trimmed.txt| |Download: http://forums.slimdevices.com/attachment.php?attachmentid=34875| +---+ lngxa's Profile: http://forums.slimdevices.com/member.php?userid=71826 View this thread: http://forums.slimdevices.com/showthread.php?t=114661 ___ Squeezecenter mailing list Squeezecenter@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/squeezecenter
[SlimDevices: SqueezeCenter] Music streaming stops intermittently
Since this is my first post, let me start by saying thank you to all the devs and community for a great product. I am having a weird problem that I need help figuring out. When I stream from LMS to squeezelite the music sometimes stops playing for 20-30 seconds and then resumes playing again. After a bit of troubleshooting I figured out that this happens because of the buffer underrun condition, but I don't know what is causing it. On the server side I am running LMS v8.1.1 on virtualized Ubuntu 20.04.2 LTS. On the client side I started with Squeezelite-X on Windows 10, but then switched to plain squeezelite to help with troubleshooting. squeezelite startup: Code: D:\squeezelite-x64.exe -n Bob -s lms.network.lan -C 60 -o Topping E30 (2- TOPPING USB DAC) [Windows WASAPI] -m 00:02:c9:aa:bb:cc -M Squeezelite-X -d all=debug -f squeezelite_03.log [01:07:59.299] stream_init:454 init stream [01:07:59.299] stream_init:455 streambuf size: 2097152 [01:07:59.299] output_init_pa:573 init output [01:07:59.299] output_init_pa:593 requested latency: 0 [01:07:59.352] output_init_common:360 outputbuf size: 3528000 [01:07:59.352] output_init_common:384 idle timeout: 6 [01:07:59.368] output_init_common:432 supported rates: 44100 [01:07:59.368] decode_init:153 init decode [01:07:59.368] register_dsd:908 using dsd to decode dsf,dff [01:07:59.368] register_alac:549 using alac to decode alc [01:07:59.368] pa_monitor:275 start monitor thread [01:07:59.430] register_faad:663 using faad to decode aac [01:07:59.430] register_vorbis:385 using vorbis to decode ogg [01:07:59.430] register_opus:329 using opus to decode ops [01:07:59.430] register_flac:332 using flac to decode ogf,flc [01:07:59.430] register_pcm:483 using pcm to decode aif,pcm [01:07:59.430] register_mad:423 using mad to decode mp3 [01:07:59.430] decode_init:194 include codecs: exclude codecs: [01:07:59.430] slimproto:898 connecting to 192.168.10.17:3483 [01:07:59.430] slimproto:937 connected [01:07:59.430] sendHELO:148 mac: 00:02:c9:aa:bb:cc [01:07:59.430] sendHELO:150 cap: CanHTTPS=1,Model=squeezelite,AccuratePlayPoints=1,HasDigitalOut=1,HasPolarityInversion=1,Balance=1,Firmware=v1.9.9-1386,ModelName=Squeezelite-X,MaxSampleRate=44100,dsf,dff,alc,aac,ogg,ops,ogf,flc,aif,pcm,mp3 [01:07:59.430] process:528 strm [01:07:59.430] process_strm:280 strm command q [01:07:59.430] decode_flush:236 decode flush [01:07:59.430] output_flush:445 flush output buffer [01:07:59.430] sendSTAT:195 STAT: STMf [01:07:59.446] process:528 strm [01:07:59.446] process_strm:280 strm command q [01:07:59.446] decode_flush:236 decode flush [01:07:59.446] output_flush:445 flush output buffer [01:07:59.446] sendSTAT:195 STAT: STMf [01:07:59.446] process:528 setd [01:07:59.446] sendSETDName:254 set playername: Bob [01:07:59.446] process:528 setd [01:07:59.446] process:528 aude [01:07:59.446] process_aude:422 enable spdif: 1 dac: 1 [01:07:59.446] process:528 audg [01:07:59.446] process_audg:440 audg gainL: 0 gainR: 0 adjust: 1 [01:07:59.446] set_volume:111 setting internal gain left: 0 right: 0 [01:08:04.301] process:528 strm [01:08:04.301] process_strm:280 strm command t [01:08:04.301] sendSTAT:195 STAT: STMt [01:08:08.296] process:528 strm squeezelite streaming song that stops playing: Code: [01:08:54.963] decode_thread:100 decode complete [01:08:54.963] sendSTAT:195 STAT: STMd [01:08:54.963] sendSTAT:195 STAT: STMt [01:08:54.980] process:528 strm [01:08:54.980] process_strm:280 strm command s [01:08:54.980] process_strm:350 strm s autostart: 1 transition period: 10 transition type: 0 codec: m [01:08:54.980] sendSTAT:195 STAT: STMf [01:08:54.980] codec_open:264 codec open: 'm' [01:08:54.980] connect_socket:164 connecting to 192.168.10.17:9000 [01:08:54.991] stream_sock:600 header: GET /stream.mp3?player=00:02:c9:aa:bb:cc HTTP/1.0 [01:08:54.991] sendSTAT:195 STAT: STMc [01:08:54.991] process_strm:384 set fade mode: 0, channels: 0, invert: 0 [01:08:54.991] process:528 audg [01:08:54.991] process_audg:440 audg gainL: 65536 gainR: 65536 adjust: 1 [01:08:54.991] set_volume:111 setting internal gain left: 65536 right: 65536 [01:08:55.044] stream_thread:331 headers: len: 491 HTTP/1.1 200 OK Server: Logitech Media Server (8.1.1 - 1610364019) Connection: close Content-Type: audio/mpeg Set-Cookie: Squeezebox-albumView=; path=/ Set-Cookie: Squeezebox-expandPlayerControl=true; path=/ Set-Cookie: Squeezebox-expanded-MY_MUSIC=1; path=/ Set-Cookie: Squeezebox-expanded-FAVORITES=0; path=/ Set-Cookie: Squeezebox-expanded-PLUGINS=0; path=/ Set-Cookie: Squeezebox-expanded-PLUGIN_MY_APPS_MODULE_NAME=0; path=/ Set-Cookie: Squeezebox-expanded-RADIO=0; path=/ [01:08:55.044] sendRESP:226 RESP [01:08:55.064] _check_lame_header:163 gapless: skip: 2257 samples: 10164756
