Radio station stops playing

[bpa]

I thought my player stopped at 16.01. It wasn't playing at 16.04.

I didn't look at your logs in detail - just trying to match the timing against my logs.

On my logs - my player stopped at 16:01 and then it retried, reconnected continued until about 16:04 which was the 32Khz->44Khz breakdown (I think).

The 15 sec radio Buffer may be enough to ride out the first issue.

Looking again at the 16:01 event to see if there is any indication why the end of "Cherry Red" stream which was followed by a Station ID.
The Squeezeplay log at 15:00 (which is really 16:00) shows buffer fullness dropping to 0% and then underrun. The "underrun" messages is sent by player to LMS and LMS logs has very similar time stamp 16:01:04

20220701 15:01:04.215 ERROR  playback_callback:359 Audio underrun: used 254 frames, requested 441 frames. elapsed samples 779543793
20220701 15:01:04.232 INFO   audio.decode - Playback.lua:364 OUTPUT UNDERRUN

On the LMS log at 16:00 - the Metadata for Station ID "'Delicious Agony - Delicious Agony ID #9';" is received but no audio.
So after 30 secs, connection is closed, a new HTTP connection is made and then player gets metadata for "Delicious Agony - South Side Of The Sky Intro'"
It looks like audio for ID#9" couldn't be streamed.

[22-07-01 16:00:36.7748] Slim::Player::Protocols::HTTP::parseMetadata (286) Icy metadata received: StreamTitle='Delicious Agony - Delicious Agony ID #9';
[22-07-01 16:00:49.7748] Slim::Player::Protocols::HTTP::readMetaData (205) Metadata byte not read, trying again: Resource temporarily unavailable
[22-07-01 16:01:04.2330] Slim::Player::StreamingController::playerOutputUnderrun (2261) SqueezeplayMAC decoder: 0 / output: 0
[22-07-01 16:01:04.2333] Slim::Player::StreamingController::_setPlayingState (2399) new playing state BUFFERING
[22-07-01 16:01:04.3599] Slim::Player::Player::_buffering (1163) Buffering... 0 / 120000
.
. (30 secs later)
.
[22-07-01 16:01:34.7601] Slim::Player::Player::_buffering (1163) Buffering... 0 / 120000
[22-07-01 16:01:35.0617] Slim::Player::StreamingController::jumpToTime (2188) SqueezeplayMAC
[22-07-01 16:01:35.0625] Slim::Player::StreamingController::_Stop (628) Song queue is now 0
[22-07-01 16:01:35.0630] Slim::Formats::RemoteStream::DESTROY (339) Slim::Player::Protocols::HTTP - in DESTROY
[22-07-01 16:01:35.0632] Slim::Formats::RemoteStream::DESTROY (340) Slim::Player::Protocols::HTTP About to close socket to: [http://deliciousagony.streamguys1.com/]
[22-07-01 16:01:35.0634] Slim::Player::StreamingController::_setPlayingState (2399) new playing state STOPPED
[22-07-01 16:01:35.0636] Slim::Player::StreamingController::_setStreamingState (2408) new streaming state IDLE
[22-07-01 16:01:35.0638] Slim::Player::StreamingController::_Stream (1155) SqueezeplayMAC got song from params, song index 0
[22-07-01 16:01:35.0641] Slim::Player::StreamingController::_Stream (1229) Song queue is now 0
[22-07-01 16:01:35.0642] Slim::Player::StreamingController::_Stream (1232) SqueezeplayMAC preparing to stream song index 0
[22-07-01 16:01:35.0644] Slim::Player::Song::open (362) http://deliciousagony.streamguys1.com/
[22-07-01 16:01:35.0652] Slim::Player::TranscodingHelper::getConvertCommand2 (490) Error: Didn't find any command matches for type: mp3
[22-07-01 16:01:35.0655] Slim::Player::Song::open (394) seek=false time=0 canSeek=0SEEK_ERROR_MP3_UNKNOWN_DURATION
[22-07-01 16:01:35.0659] Slim::Player::TranscodingHelper::getConvertCommand2 (493) Matched: mp3->mp3 via: -
[22-07-01 16:01:35.0660] Slim::Player::Song::open (424) Transcoder: streamMode=I, streamformat=mp3
[22-07-01 16:01:35.0663] Slim::Player::Song::open (480) Opening stream (no direct streaming) using Slim::Player::Protocols::HTTP [http://deliciousagony.streamguys1.com/]
[22-07-01 16:01:35.0667] Slim::Formats::RemoteStream::new (69) Opening connection to http://deliciousagony.streamguys1.com/: [deliciousagony.streamguys1.com on port 80 with path / with timeout 15]
[22-07-01 16:01:35.4166] Slim::Formats::RemoteStream::request (144) Request: GET / HTTP/1.0
Cache-Control: no-cache
Connection: close
Accept: */*
Host: deliciousagony.streamguys1.com
Range: bytes=0-
User-Agent: iTunes/4.7.1 (Linux; N; Debian; x86_64-linux; EN; utf8) SqueezeCenter, Squeezebox Server, Logitech Media Server/8.3.0/1649774106
Icy-MetaData: 1

[22-07-01 16:01:35.6197] Slim::Formats::RemoteStream::request (151) Response: HTTP/1.0 200 OK
[22-07-01 16:01:35.6244] Slim::Player::Protocols::HTTP::parseHeaders (826) Setting new title for http://deliciousagony.streamguys1.com/, Delicious Agony
[22-07-01 16:01:35.6259] Slim::Formats::RemoteStream::request (217) Opened stream!
[22-07-01 16:01:35.6263] Slim::Player::Song::open (510) URL is a song (audio): http://deliciousagony.streamguys1.com/, type=mp3
[22-07-01 16:01:35.6282] Slim::Player::StreamingController::_Stream (1301) SqueezeplayMAC stream
[22-07-01 16:01:35.6290] Slim::Player::Squeezebox::stream_s (1015) Starting decoder with format: m flags: 0x0 autostart: 1 buffer threshold: 240 output threshold: 1 samplesize: ? samplerate: ? endian: ? channels: ?
[22-07-01 16:01:35.6292] Slim::Player::StreamingController::_Stream (1338) Song queue is now 0
[22-07-01 16:01:35.6293] Slim::Player::StreamingController::_setPlayingState (2399) new playing state BUFFERING
[22-07-01 16:01:35.6294] Slim::Player::StreamingController::_setStreamingState (2408) new streaming state STREAMING
[22-07-01 16:01:35.6323] Slim::Player::Squeezebox2::directHeaders (480) Processing headers for direct streaming:
HTTP/1.1 200 OK
Server: Logitech Media Server (8.3.0 - 1649774106)
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=0; path=/
Set-Cookie: Squeezebox-expanded-PLUGIN_MY_APPS_MODULE_NAME=1; path=/
Set-Cookie: Squeezebox-expanded-RADIO=1; path=/

[22-07-01 16:01:35.7542] Slim::Player::Player::_buffering (1163) Buffering... 0 / 245760
[22-07-01 16:01:35.8246] Slim::Player::Protocols::HTTP::readMetaData (212) Metadata size: 64
[22-07-01 16:01:35.8249] Slim::Player::Protocols::HTTP::readMetaData (238) Metadata: StreamTitle='Delicious Agony - South Side Of The Sky Intro';
[22-07-01 16:01:35.8251] Slim::Player::Protocols::HTTP::parseMetadata (286) Icy metadata received: StreamTitle='Delicious Agony - South Side Of The Sky Intro';
[22-07-01 16:01:36.0553] Slim::Player::Player::_buffering (1163) Buffering... 0 / 245760

[bpa]

Forgot to add my conclusion.

The same stream "event" was seen by two player means the issues is a Station one. It looks like, for some reason, after the 1 hr "Cherry red" program, the "ID #9" never played = so there was a gap in the audio stream.
As connection was closed after 30 secs by my end - it is not clear whether stream would have continued playing when the "Delicious Agony - South Side Of The Sky Intro'"" .

It is a bit suspicious that problem happens when two promos are back to back which I haven't seen before and the second promo was 32kHz

20220701 15:01:35.733 DEBUG  audio.decode - Playback.lua:397 resume decoder, 9504 bytes buffered, decode threshold 2048
20220701 15:01:35.733 DEBUG  audio.decode - decode_resume_decoder:577 decode_resume_decoder
20220701 15:01:35.733 DEBUG  audio.decode - decode_resume_decoder_handler:118 resume_decoder decode state: 1 audio state 0
20220701 15:01:35.733 DEBUG  audio.decode - debug_fullness:108 fullness: 9504 / 0 | 0.30% / 0.00%
20220701 15:01:35.734 DEBUG  audio.codec - xing_parse:79 no xing header
20220701 15:01:35.734 DEBUG  audio.codec - decode_mad_output:413 Skip encoder_delay=529 pcm->length=1152 offset=529
20220701 15:01:35.734 DEBUG  audio.decode - decode_output_samples:279 first buffer sample_rate=32000
20220701 15:01:35.825 DEBUG  audio.decode - Playback.lua:451 0.0%/4.3%