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.
UPDATE: I reran the test again, and now I see the error, so I had to rewrite the post. 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: [20:02:06.590] sendSTAT:195 STAT: STMs [20:02:07.600] sendSTAT:195 STAT: STMt [20:02:09.319] sendSTAT:195 STAT: STMt [20:02:09.320] process:527 strm [20:02:09.337] process_strm:280 strm command t [20:02:09.343] sendSTAT:195 STAT: STMt [20:02:10.353] sendSTAT:195 STAT: STMt [20:02:12.377] sendSTAT:195 STAT: STMt [20:02:13.389] sendSTAT:195 STAT: STMt ... [20:02:23.318] process:527 strm [20:02:23.324] process_strm:280 strm command t [20:02:23.330] sendSTAT:195 STAT: STMt [20:02:24.340] sendSTAT:195 STAT: STMt [20:02:26.363] sendSTAT:195 STAT: STMt [20:02:27.319] process:527 strm [20:02:27.319] process_strm:280 strm command t ... It was showing these messages continuously. Then, the issue came up after the first 6 minutes of streaming, and the logs continued like this: [20:08:41.318] sendSTAT:195 STAT: STMt [20:08:41.318] sendSTAT:195 STAT: STMo [20:08:41.319] process:527 strm [20:08:41.324] process_strm:280 strm command t [20:08:41.325] sendSTAT:195 STAT: STMt [20:08:41.325] process:527 strm [20:08:41.326] process_strm:280 strm command p [20:08:41.326] sendSTAT:195 STAT: STMp [20:08:41.327] process_strm:316 pause interval: 0 [20:08:41.447] process:527 strm [20:08:41.447] process_strm:280 strm command t [20:08:41.450] sendSTAT:195 STAT: STMt [20:08:41.748] process:527 strm [20:08:41.748] process_strm:280 strm command t [20:08:41.749] sendSTAT:195 STAT: STMt [20:08:42.048] process:527 strm [20:08:42.049] process_strm:280 strm command t [20:08:42.050] sendSTAT:195 STAT: STMt [20:08:42.349] process:527 strm [20:08:42.349] process_strm:280 strm command t It continued for exactly 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: [20:09:11.814] process_strm:280 strm command t [20:09:11.815] sendSTAT:195 STAT: STMt [20:09:12.114] process:527 strm [20:09:12.114] process_strm:280 strm command t [20:09:12.116] sendSTAT:195 STAT: STMt [20:09:12.415] process:527 strm [20:09:12.415] process_strm:280 strm command q [20:09:12.419] decode_flush:236 decode flush [20:09:12.425] output_flush:438 flush output buffer [20:09:12.427] sendSTAT:195 STAT: STMf [20:09:12.643] process:527 audg [20:09:12.643] process_audg:439 audg gainL: 20992 gainR: 20992 adjust: 1 [20:09:12.651] set_volume:111 setting internal gain left: 20992 right: 20992 [20:09:12.654] process:527 strm [20:09:12.656] process_strm:280 strm command s [20:09:12.661] process_strm:350 strm s autostart: 1 transition period: 3 transition type: 0 codec: m [20:09:12.668] sendSTAT:195 STAT: STMf [20:09:12.670] codec_open:264 codec open: 'm' [20:09:12.676] connect_socket:158 connecting to 192.168.0.60:9002 [20:09:12.679] stream_sock:591 header: GET /stream.mp3?player=70:85:c2:a8:ce:68 HTTP/1.0 [20:09:12.685] sendSTAT:195 STAT: STMc [20:09:12.688] process_strm:383 set fade mode: 0 [20:09:12.694] process:527 audg [20:09:12.701] process_audg:439 audg gainL: 20992 gainR: 20992 adjust: 1 [20:09:12.707] set_volume:111 setting internal gain left: 20992 right: 20992 [20:09:12.767] 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=/ [20:09:12.769] sendRESP:226 RESP [20:09:12.780] mad_decode:247 setting track_start [20:09:12.782] mad_decode:276 gapless: skipping 529 frames at start [20:09:12.784] mad_decode:235 mad_frame_decode error: bad main_data_begin pointer [20:09:12.800] _output_frames:64 start buffer frames: 32879 [20:09:12.801] _output_frames:152 track start sample rate: 44100 replay_gain: 0 [20:09:12.803] pa_callback:525 pad with silence [20:09:12.809] sendSTAT:195 STAT: STMs [20:09:12.814] sendSTAT:195 STAT: STMt [20:09:13.164] stream_thread:398 end of stream [20:09:13.165] sendDSCO:214 DSCO: 0 [20:09:13.318] process:527 strm [20:09:13.318] process_strm:280 strm command t [20:09:13.325] sendSTAT:195 STAT: STMt The first error we see is "mad_frame_decode error: bad main_data_begin pointer" Playback continued for another 15 seconds, before I saw some socket errors: [20:09:16.354] sendSTAT:195 STAT: STMt [20:09:30.921] sendSTAT:195 STAT: STMt [20:09:30.932] send_packet:114 failed writing to socket: Unknown error [20:09:30.932] slimproto_run:563 error reading from socket: Unknown error [20:09:31.059] slimproto:932 connected [20:09:31.059] sendHELO:148 mac: 70:85:c2:a8:ce:68 [20:09:31.065] sendHELO:150 cap: CanHTTPS=1,Model=squeezelite,AccuratePlayPoints=1,HasDigitalOut=1,HasPolarityInversion=1,Firmware=v1.9.8-1313,ModelName=SqueezeLite,MaxSampleRate=768000,dsf,dff,alc,aac,ogg,ops,ogf,flc,aif,pcm,mp3 [20:09:31.068] process:527 setd [20:09:31.068] sendSETDName:254 set playername: SqueezeLite-bogan-admin [20:09:31.070] process:527 setd [20:09:31.072] process:527 aude [20:09:31.073] process_aude:421 enable spdif: 1 dac: 1 [20:09:31.075] process:527 audg [20:09:31.083] process_audg:439 audg gainL: 20992 gainR: 20992 adjust: 1 [20:09:31.085] set_volume:111 setting internal gain left: 20992 right: 20992 [20:09:32.090] sendSTAT:195 STAT: STMt [20:09:33.105] sendSTAT:195 STAT: STMt [20:09:35.124] sendSTAT:195 STAT: STMt [20:09:35.318] process:527 strm [20:09:35.318] process_strm:280 strm command t So playback continued for another 1.5 minutes: [20:09:35.322] sendSTAT:195 STAT: STMt [20:09:36.342] sendSTAT:195 STAT: STMt [20:09:38.351] sendSTAT:195 STAT: STMt [20:09:39.317] process:527 strm [20:09:39.318] process_strm:280 strm command t ... [20:09:49.396] sendSTAT:195 STAT: STMt [20:09:50.405] sendSTAT:195 STAT: STMt [20:09:51.415] sendSTAT:195 STAT: STMt [20:09:53.434] sendSTAT:195 STAT: STMt Then the error came up again: [20:10:11.995] mad_decode:207 end of stream [20:11:00.038] decode_thread:100 decode complete [20:11:00.038] sendSTAT:195 STAT: STMd [20:11:00.039] send_packet:114 failed writing to socket: Unknown error [20:11:00.039] sendSTAT:195 STAT: STMt [20:11:00.045] send_packet:114 failed writing to socket: Unknown error [20:11:00.047] slimproto_run:563 error reading from socket: Unknown error [20:11:00.171] slimproto:932 connected [20:11:00.171] sendHELO:148 mac: 70:85:c2:a8:ce:68 [20:11:00.177] sendHELO:150 cap: CanHTTPS=1,Model=squeezelite,AccuratePlayPoints=1,HasDigitalOut=1,HasPolarityInversion=1,Firmware=v1.9.8-1313,ModelName=SqueezeLite,MaxSampleRate=768000,dsf,dff,alc,aac,ogg,ops,ogf,flc,aif,pcm,mp3 [20:11:00.183] slimproto_run:715 output underrun [20:11:00.185] sendSTAT:195 STAT: STMu [20:11:00.192] process:527 setd [20:11:00.194] sendSETDName:254 set playername: SqueezeLite-bogan-admin [20:11:00.200] process:527 setd [20:11:00.206] process:527 aude [20:11:00.207] process_aude:421 enable spdif: 1 dac: 1 [20:11:00.213] process:527 audg [20:11:00.215] process_audg:439 audg gainL: 20992 gainR: 20992 adjust: 1 [20:11:00.216] set_volume:111 setting internal gain left: 20992 right: 20992 [20:11:00.327] process:527 strm [20:11:00.327] process_strm:280 strm command t [20:11:00.332] sendSTAT:195 STAT: STMt [20:11:05.318] process:527 strm [20:11:05.318] process_strm:280 strm command t [20:11:05.319] sendSTAT:195 STAT: STMt [20:11:09.768] slimproto_stop:972 slimproto stop [20:11:10.428] decode_close:221 close decode [20:11:10.428] stream_close:502 close stream [20:11:10.430] output_close_pa:613 close output These socket errors were appearing while playback was going on. They appeared AFTER playback had stopped and already resumed, thus we can say that the errors were a symptom of the failure, but the failure happened somewhere else. I hope your knowledge of the code will point you towards the real cause of the problem. 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 plugins@lists.slimdevices.com http://lists.slimdevices.com/mailman/listinfo/plugins
