Announcement

**lngxa** · 2021-05-31, 20:44

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

Attached Files

server_03_single_song_trimmed.txt (118.4 KB, 3 views)

**lngxa** · 2021-06-02, 05:35

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/showt...very-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.

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
[B][12:10:50.176] stream_thread:404 end of stream (69787849 bytes)[/B]
[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: [B]19354603[/B]

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.

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 [B]3445 [/B]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 [B]received bytesL: 18918306[/B] 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 squeezelite does not get any more data from the stream buffer, but keeps playing song from the output buffer until that runs dry and it sends STMo to the server

Code:

[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: [B]STMo[/B]
[01:21:00.018] sendSTAT:200 received bytesL: 18918306 streambuf: 2019 [B]outputbuf: 0[/B] calc elapsed: 618638 real elapsed: 619203 (diff: -565) device: 10 delay: 16

It then takes a bit of time to establish new TCP connection and get the rest of the song from the server. This all results in song playback stopping for 10-30 seconds and then resuming the play.

Here is what I think is happening. Server sends data to the client even though client's stream buffer is full (is server supposed to wait for the buffer to drain?). This is indicated in the STMt fullness field that client is sending to the server. After server is done sending all of the data to the client a lot of that data is sitting in the TCP buffers on the client machine yet to be retrieved by the client. Client takes more than 60 seconds to get all of that data from the TCP buffer and at some point TCP RST packet is received from the server. Per Microsoft documentation: RST causes the resources allocated to the connection to be immediately released and all other information about the connection erased. So RST receival destroys TCP buffers associated with that connection and now client can't get the data from the buffer.

**lngxa** · 2021-06-02, 05:45

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?

**bpa** · 2021-06-02, 08:31

Originally posted by lngxa

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.

**ralphy** · 2021-06-02, 13:16

There have been similiar discussions in the squeezelite thread.

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?

**lngxa** · 2021-06-04, 06:59

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.

Originally posted by bpa

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.

Originally posted by bpa

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.

Originally posted by ralphy

There have been similiar discussions in the squeezelite thread.

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/showt...very-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** · 2021-06-05, 19:11

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: [FONT=Arial Black]2097152[/FONT]
[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: [FONT=Arial Black]3528000[/FONT]
[01:10:29.043] output_init_common:384 idle timeout: 60000
[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
[FONT=Arial Black][01:10:40.529] process_strm:280 strm command s[/FONT]
[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
[FONT=Arial Black][01:10:40.544] sendSTAT:195 STAT: STMc[/FONT]
[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
[FONT=Arial Black][01:10:40.638] stream_thread:428 streambuf read 7300 bytes[/FONT]                [FONT=Arial Black][I]<-- first data arriving[/I][/FONT]
[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
[21-06-01 01:10:42.4985] Slim::Player::Song::open (470) Opening stream (no direct streaming) using Slim::Player::Protocols::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:10:42.4990] Slim::Player::Protocols::File::open (80) duration: [634.333] size: [19354603] endian [] offset: [35733] for 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.4991] Slim::Player::Protocols::File::open (97) Opening file /mnt/media/music/popular/Led.Zeppelin/In.Through.the.Out.Door.(1979)/05 - Led Zeppelin - Carouselambra.mp3
[21-06-01 01:10:42.5002] Slim::Player::Protocols::File::open (189) Seeking in 35733 into /mnt/media/music/popular/Led.Zeppelin/In.Through.the.Out.Door.(1979)/05 - Led Zeppelin - Carouselambra.mp3
[21-06-01 01:10:42.5004] Slim::Player::Song::open (491) URL is a song (audio): file:///mnt/media/music/popular/Led.Zeppelin/In.Through.the.Out.Door.(1979)/05%20-%20Led%20Zeppelin%20-%20Carouselambra.mp3, type=mp3
[21-06-01 01:10:42.5058] Slim::Player::Squeezebox::sendFrame (1133) sending squeezebox frame: audg, length: 22
[21-06-01 01:10:42.5059] Slim::Networking::Select::_writeNoBlock (72) fileno: [28] Wrote 28 bytes
[21-06-01 01:10:42.5061] Slim::Player::StreamingController::_Stream (1282) 00:02:c9:13:08:d0: stream
[FONT=Arial Black][21-06-01 01:10:42.5064] Slim::Player::Squeezebox::stream_s (542) stream_s called[/FONT]: format: mp3 url: 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.5067] Slim::Player::Squeezebox::stream_s (907) flags: 0
[21-06-01 01:10:42.5068] Slim::Player::Squeezebox::stream_s (933) Using smart transition mode
[21-06-01 01:10:42.5070] Slim::Player::Squeezebox::stream_s (993) Starting decoder with format: m flags: 0x0 autostart: 1 buffer threshold: 255 output threshold: 1 samplesize: ? samplerate: ? endian: ? channels: ?
[21-06-01 01:10:42.5072] Slim::Player::Squeezebox::stream_s (1024) sending strm frame of length: 77 request string: [GET /stream.mp3?player=00:02:c9:13:08:d0 HTTP/1.0

]

...

[21-06-01 01:10:42.5187] Slim::Networking::Slimproto::_stat_handler (778) FACTORYTEST	event=stat	mac=00:02:c9:13:08:d0	signalstrength=65535
[21-06-01 01:10:42.5188] Slim::Networking::Slimproto::_stat_handler (784) 00:02:c9:13:08:d0: STAT-STMc: fullness=0, output_fullness=-1, elapsed=0.000
[21-06-01 01:10:42.5190] Slim::Networking::Slimproto::_stat_handler (811) 00:02:c9:13:08:d0 Squeezebox stream status:
	event_code:      STMc
	bytes_rec_H      0
	bytes_rec_L      0
	fullness:        0 (0%)
	bufferSize      2097152
	fullness         0
	bytes_received   0
	signal_strength: 65535
	jiffies:         1655165765
	voltage:         0
[21-06-01 01:10:42.5191] Slim::Networking::Slimproto::_stat_handler (823)
	output size:     3528000
	output fullness: 0
	elapsed seconds: 0
[21-06-01 01:10:42.5192] Slim::Networking::Slimproto::_stat_handler (835)
	elapsed milliseconds: 0
	server timestamp:     0

...

[21-06-01 01:10:42.6071] Slim::Web::HTTP::processHTTP (342) Reading request...
[21-06-01 01:10:42.6078] Slim::Web::HTTP::processHTTP (359) HTTP request: from 192.168.10.100:60755 (Slim::Web::HTTP::ClientConn=GLOB(0x5615ba8704c0)) for GET HTTP/1.0 /stream.mp3?player=00:02:c9:13:08:d0
[21-06-01 01:10:42.6081] Slim::Web::HTTP::processHTTP (366) Raw request headers: [
GET /stream.mp3?player=00:02:c9:13:08:d0 HTTP/1.0

]
...
[21-06-01 01:10:42.6097] Slim::Web::HTTP::processURL (782) processURL Clients: 192.168.10.100:60754
[21-06-01 01:10:42.6108] Slim::Web::HTTP::generateHTTPResponse (1037) Generating response for (mp3, audio/mpeg) stream.mp3
[21-06-01 01:10:42.6111] Slim::Web::HTTP::generateHTTPResponse (1181) Disabling keep-alive for stream.mp3
[21-06-01 01:10:42.6127] Slim::Web::HTTP::processHTTP (735) Response Headers: [
HTTP/1.1 200 OK
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=/

]
[21-06-01 01:10:42.6129] Slim::Web::HTTP::processHTTP (738) End request: keepAlive: [] - waiting for next request for Slim::Web::HTTP::ClientConn=GLOB(0x5615ba8704c0) on connection = close
[21-06-01 01:10:42.6133] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun...
[FONT=Arial Black][21-06-01 01:10:42.6137] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 491 to 192.168.10.100[/FONT]                       [FONT=Arial Black]<-- first data sent[/FONT]

**lngxa** · 2021-06-05, 20:05

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)
[FONT=Arial Black][21-06-01 01:10:42.7391] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 32768 to 192.168.10.100[/FONT]              [FONT=Arial Black] <-- last data sent before pause[/FONT]
[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      [FONT=Arial][FONT=Arial Black]2393886[/FONT][/FONT]
	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
[FONT=Arial Black][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[/FONT]
[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.

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] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun...
[21-06-01 01:10:42.7935] Slim::Web::HTTP::sendStreamingResponse (2276) (audio: 32768 bytes)
[21-06-01 01:10:42.7937] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 32768 to 192.168.10.100

...

[21-06-01 01:10:42.8297] Slim::Web::HTTP::sendStreamingResponse (2276) (audio: 32768 bytes)
[21-06-01 01:10:42.8298] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 32768 to 192.168.10.100
[21-06-01 01:10:42.8300] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun...
[21-06-01 01:10:42.8301] Slim::Web::HTTP::sendStreamingResponse (2276) (audio: 32768 bytes)
[21-06-01 01:10:42.8302] Slim::Web::HTTP::sendStreamingResponse (2425) Streamed 32768 to 192.168.10.100                     [FONT=Arial Black]<-- last data before the second pause[/FONT]

...

[21-06-01 01:10:44.7826] Slim::Networking::Slimproto::_stat_handler (778) FACTORYTEST	event=stat	mac=00:02:c9:13:08:d0	signalstrength=65535                          [FONT=Arial Black] <-- first STMt after pause[/FONT]
[21-06-01 01:10:44.7829] Slim::Networking::Slimproto::_stat_handler (784) 00:02:c9:13:08:d0: STAT-STMt: fullness=2094020, output_fullness=3325696, elapsed=1.986
[21-06-01 01:10:44.7831] 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      2448379
	fullness:        2094020 (99%)
	bufferSize      2097152
	fullness         2094020
	bytes_received   2448379
	signal_strength: 65535
	jiffies:         1655168031
	voltage:         0
[21-06-01 01:10:44.7834] Slim::Networking::Slimproto::_stat_handler (823)
	output size:     3528000
	output fullness: 3325696
	elapsed seconds: 1
[21-06-01 01:10:44.7836] Slim::Networking::Slimproto::_stat_handler (835)
	elapsed milliseconds: 1986
	server timestamp:     0

Code:

[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
[01:10:41.214] stream_thread:428 streambuf read 4698 bytes
[01:10:41.315] stream_thread:428 streambuf read 1879 bytes
[01:10:41.416] stream_thread:428 streambuf read 3236 bytes
[01:10:41.517] stream_thread:428 streambuf read 1462 bytes
[01:10:41.618] stream_thread:428 streambuf read 3132 bytes
[01:10:41.719] stream_thread:428 streambuf read 3549 bytes
[01:10:41.820] stream_thread:428 streambuf read 3445 bytes
[01:10:41.920] stream_thread:428 streambuf read 1775 bytes
[01:10:42.020] stream_thread:428 streambuf read 3341 bytes
[01:10:42.120] stream_thread:428 streambuf read 3967 bytes
[01:10:42.221] stream_thread:428 streambuf read 3549 bytes
[01:10:42.322] stream_thread:428 streambuf read 3236 bytes
[01:10:42.423] stream_thread:428 streambuf read 3654 bytes
[01:10:42.524] stream_thread:428 streambuf read 1775 bytes
[01:10:42.624] stream_thread:428 streambuf read 3757 bytes
[01:10:42.725] stream_thread:428 streambuf read 1670 bytes
[01:10:42.812] sendSTAT:166 ms_played: 1986 (frames_played: 87318 device_frames: 441)
[01:10:42.812] sendSTAT:195 STAT: STMt
[FONT=Arial Black][01:10:42.812] sendSTAT:200 received bytesL: 2448379 streambuf: 2094020 outputbuf: 3325696 calc elapsed: 1986 real elapsed: 2000 (diff: -14) device: 10 delay: 16[/FONT]
[01:10:42.826] stream_thread:428 streambuf read 3131 bytes
[01:10:42.926] stream_thread:428 streambuf read 3445 bytes
[01:10:43.027] stream_thread:428 streambuf read 1879 bytes

I calculated that LMS has sent out 3112960 bytes in this second burst (since last pause) and 9109995 (8.68 MB) total. squeezelite has received 2448379 bytes (2.33 MB). Difference between sent and received data is 6661616 bytes (6.35 MB) or 218 seconds of playback.

since second pause is almost a minute long we see keep-alive packets being sent to make sure the TCP session does not time out.

**lngxa** · 2021-06-05, 21:16

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...                     [FONT=Arial Black]<-- streaming resumes after the second pause[/FONT]
[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                 [FONT=Arial Black]<-- streaming pauses for the third time[/FONT]

...

[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: 5997035                    5997035            2393886          3603149         118 seconds
2nd burst: 3112960                    9109995            2448379          6661616         218 seconds
3rd burst: 2129920                    11239915           4216443          7023472         230 seconds
4th burst: 2097152                    13337067           6373697          6963370         228 seconds
5th burst: 2097152                    15434219           8421048          7013171         229 seconds
6th burst: 2097152                    17531371           10549011         6982360         228 seconds
7th burst: 1823723                    19355094           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                            [FONT=Arial Black] <-- last data streamed[/FONT]
[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: [FONT=Arial Black]19354603[/FONT]
[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)
[21-06-01 01:16:09.2690] Slim::Web::HTTP::sendStreamingResponse (2414) $peeraddr{$httpClient} is: 192.168.10.100
[21-06-01 01:16:09.2692] Slim::Web::HTTP::sendStreamingResponse (2415) Got nothing for streaming data to 192.168.10.100                                                                 
[21-06-01 01:16:09.6701] Slim::Web::HTTP::sendStreamingResponse (2168) sendStreaming response begun...
[21-06-01 01:16:09.6704] Slim::Web::HTTP::sendStreamingResponse (2289) Found an empty chunk on the queue - dropping the streaming connection.
[21-06-01 01:16:09.6706] Slim::Web::HTTP::closeStreamingSocket (2532) Closing streaming socket
[21-06-01 01:16:09.6709] Slim::Web::HTTP::closeHTTPSocket (2466) Closing HTTP socket Slim::Web::HTTP::ClientConn=GLOB(0x5615ba8704c0) with 192.168.10.100:60755 [FONT=Arial Black](closed normally)
[/FONT]
...

[21-06-01 01:16:11.0045] Slim::Networking::Slimproto::_stat_handler (778) FACTORYTEST	event=stat	mac=00:02:c9:13:08:d0	signalstrength=65535
[21-06-01 01:16:11.0047] Slim::Networking::Slimproto::_stat_handler (784) 00:02:c9:13:08:d0: STAT-STMt: fullness=2093499, output_fullness=3325264, elapsed=328.110
[21-06-01 01:16:11.0050] 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      12661166
	fullness:        2093499 (99%)
	bufferSize      2097152
	fullness         2093499
	bytes_received   12661166
	signal_strength: 65535
	jiffies:         1655494234
	voltage:         0
[21-06-01 01:16:11.0052] Slim::Networking::Slimproto::_stat_handler (823)
	output size:     3528000
	output fullness: 3325264
	elapsed seconds: 328
[21-06-01 01:16:11.0054] Slim::Networking::Slimproto::_stat_handler (835)
	elapsed milliseconds: 328110
	server timestamp:     0

Nothing wrong from the LMS point of view, it has read all the data from the file and streamed it to the client. Note that LMS closes socket at 01:16:09.670.

Now lets look at what happens with the TCP stream:

Client machine receives last data packet (frame 17677) from the server at 01:18:31.892, but we know that LMS closed socket at 01:16:09.670. That's 144 second difference (accounting for 2 sec difference between the machines), that's how long it took to drain TCP send buffers on the LMS server machine. We already calculated that there was 219 seconds of data in the TCP send + TCP receive buffers when LMS finished streaming and closed the socket. Now that TCP send buffer is empty we can try to calculate how much data there was in the TCP receive buffers on the client machine when frame 17677 was received: 219-144=75 seconds.

Since Linux TCP stack on the server only waits 60 seconds (timeout controlled by net.ipv4.tcp_fin_timeout) for response to the FIN packet we already know that client is not going to be able to send back FIN,ACK in time.

**lngxa** · 2021-06-05, 22:00

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        [FONT=Arial Black]<-- first STMt after LMS closed connection[/FONT]
[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                              [FONT=Arial Black]<-- frame 17677 with TCP FIN arrives[/FONT]
[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                               [FONT=Arial Black]<-- last read from the stream buffer[/FONT]
[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)
[FONT=Arial Black][01:21:00.018] sendSTAT:195 STAT: STMo[/FONT]
[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
[FONT=Arial Black][01:21:00.028] process_strm:280 strm command p[/FONT]
[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] sendSTAT:200 received bytesL: 18918306 streambuf: 2019 outputbuf: 0 calc elapsed: 618654 real elapsed: 619219 (diff: -565) device: 10 delay: 32
[01:21:00.028] process_strm:316 pause interval: 0
[01:21:00.160] process:528 strm
[01:21:00.160] process_strm:280 strm command t

squeezelite performs last successfull read from the stream buffer at 01:19:41.522 which matches with the arrival of RST packet from the server. Once Windows receives RST packet it destroys TCP connection and associated buffers so squeezelite has nothing to read from. Once squeezelite buffer empties it pauses music and sends STMo to the sever, 20-30 seconds later music playback resumes.

**lngxa** · 2021-06-06, 00:16

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.

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!

**lngxa** · 2021-06-06, 16:47

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.

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.

**ralphy** · 2021-06-08, 14:08

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.

**lngxa** · 2021-06-09, 06:59

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.

Announcement

Music streaming stops intermittently

Music streaming stops intermittently

Comment

Comment

Comment

Comment

Comment

Comment

Comment

Comment

Comment

Comment

Comment

Comment

Comment

Comment