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 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: *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
--------------------
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.
+-------------------------------------------------------------------+
|Filename: tcp_session_rst_01.jpg |
|Download: http://forums.slimdevices.com/attachment.php?attachmentid=34881|
+-------------------------------------------------------------------+
------------------------------------------------------------------------
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
[email protected]
http://lists.slimdevices.com/mailman/listinfo/squeezecenter
