ralphy wrote: > Well that's more encouraging than your initial test results. 'This is > the change' > (https://github.com/ralph-irving/squeezelite/commit/8f76e82c5d27fddc821412f9f01f5170f930070d). > > I'd already pulled the r1313 test build before seeing your post. > > Thanks for the suggestion. I will likely need to add more logging to > figure out what's happening.
Ah, I see it's written in C, so obviously no try/catch is possible. Looking at the code, I see that if send() failed (because it's blocked or lost the connection) it will retry 10 times, pausing for 1 second, and if it can't write, log a warning "failed writing to socket". I agree that this code might result in the "pause" observed, but so far, I didn't see anything in the logs to indicate it failed to send_packet(). Armed with this knowledge, I reran my tests, with debug logs. While streaming normally, I see this: [19:20:14.327] sendSTAT:195 STAT: STMt [19:20:15.337] sendSTAT:195 STAT: STMt [19:20:17.359] sendSTAT:195 STAT: STMt [19:20:18.321] process:527 strm [19:20:18.321] process_strm:280 strm command t [19:20:18.322] sendSTAT:195 STAT: STMt [19:20:19.339] sendSTAT:195 STAT: STMt [19:20:21.352] sendSTAT:195 STAT: STMt [19:20:23.320] sendSTAT:195 STAT: STMt [19:20:23.320] process:527 strm [19:20:23.321] process_strm:280 strm command t [19:20:23.328] sendSTAT:195 STAT: STMt [19:20:24.340] sendSTAT:195 STAT: STMt [19:20:26.358] sendSTAT:195 STAT: STMt [19:20:26.358] sendSTAT:195 STAT: STMo It was showing these messages continuously. Then, the issue came up after the first 6 minutes of streaming, and the logs continued like this: [19:20:26.360] process:527 strm [19:20:26.366] process_strm:280 strm command p [19:20:26.366] sendSTAT:195 STAT: STMp [19:20:26.367] process_strm:316 pause interval: 0 [19:20:26.488] process:527 strm [19:20:26.488] process_strm:280 strm command t [19:20:26.489] sendSTAT:195 STAT: STMt [19:20:26.788] process:527 strm [19:20:26.788] process_strm:280 strm command t [19:20:26.790] sendSTAT:195 STAT: STMt [19:20:27.089] process:527 strm [19:20:27.089] process_strm:280 strm command t [19:20:27.090] sendSTAT:195 STAT: STMt [19:20:27.321] process:527 strm [19:20:27.321] process_strm:280 strm command t [19:20:27.322] sendSTAT:195 STAT: STMt ... It continued for about 30 seconds with these sendSTAT for stream command "t" (I think this means 'track' latency) And as soon as the audio resumed, I saw this: [19:20:57.456] decode_flush:236 decode flush [19:20:57.462] output_flush:438 flush output buffer [19:20:57.463] sendSTAT:195 STAT: STMf [19:20:57.535] process:527 audg [19:20:57.536] process_audg:439 audg gainL: 20992 gainR: 20992 adjust: 1 [19:20:57.546] set_volume:111 setting internal gain left: 20992 right: 20992 [19:20:57.552] process:527 strm [19:20:57.562] process_strm:280 strm command s [19:20:57.575] process_strm:350 strm s autostart: 1 transition period: 3 transition type: 0 codec: m [19:20:57.580] sendSTAT:195 STAT: STMf [19:20:57.588] codec_open:264 codec open: 'm' [19:20:57.595] connect_socket:158 connecting to 192.168.0.60:9002 [19:20:57.604] stream_sock:591 header: GET /stream.mp3?player=70:85:c2:a8:ce:68 HTTP/1.0 ... [19:20:57.608] sendSTAT:195 STAT: STMc [19:20:57.614] process_strm:383 set fade mode: 0 [19:20:57.623] process:527 audg [19:20:57.628] process_audg:439 audg gainL: 20992 gainR: 20992 adjust: 1 [19:20:57.633] set_volume:111 setting internal gain left: 20992 right: 20992 [19:20:57.689] stream_thread:325 headers: len: 491 HTTP/1.1 200 OK Server: Logitech Media Server (8.0.1 - 1607087403) 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=/ [19:20:57.689] sendRESP:226 RESP [19:20:57.787] mad_decode:247 setting track_start [19:20:57.788] mad_decode:276 gapless: skipping 529 frames at start [19:20:57.793] mad_decode:235 mad_frame_decode error: bad main_data_begin pointer [19:20:57.802] _output_frames:64 start buffer frames: 14447 [19:20:57.804] _output_frames:152 track start sample rate: 44100 replay_gain: 0 [19:20:57.806] pa_callback:525 pad with silence Here we see it resumed with stream command "f" (flush) and got a new socket connection. I don't know whether is is normal behavior. After that, it continued logging as it did earlier. There were no messages from the code that you changed. I see that send_stat() was called continuously, but its invocation of send_packet() did not experience any failure. I hope that helps to illuminate the problem directly. John ------------------------------------------------------------------------ foopydog's Profile: http://forums.slimdevices.com/member.php?userid=71156 View this thread: http://forums.slimdevices.com/showthread.php?t=113554 _______________________________________________ plugins mailing list [email protected] http://lists.slimdevices.com/mailman/listinfo/plugins
