Radio station stops playing

[bpa]

Just notice the squeezeplay log was 15:04 - underrun at 15:00 (i.e. 4pm). Interesting PCM log message at 15:01

Is Cherry Red" a podcast inserted into the stream ? it is very long and has no metadata during its broadcast.

15:00:47.133 DEBUG  audio.decode - Playback.lua:451 2.3%/100.0%
20220701 15:00:48.213 DEBUG  audio.decode - Playback.lua:451 2.3%/99.4%
20220701 15:00:49.338 DEBUG  audio.decode - Playback.lua:451 2.4%/99.6%
20220701 15:00:50.418 DEBUG  audio.decode - Playback.lua:451 2.0%/99.7%
20220701 15:00:51.500 DEBUG  audio.decode - Playback.lua:451 1.4%/99.9%
20220701 15:00:52.533 DEBUG  audio.decode - Playback.lua:451 0.8%/99.8%
20220701 15:00:53.612 DEBUG  audio.decode - Playback.lua:451 0.4%/99.5%
20220701 15:00:54.737 DEBUG  audio.decode - Playback.lua:451 0.0%/94.8%
20220701 15:00:55.818 DEBUG  audio.decode - Playback.lua:451 0.0%/84.0%
20220701 15:00:56.898 DEBUG  audio.decode - Playback.lua:451 0.0%/73.2%
20220701 15:00:57.933 DEBUG  audio.decode - Playback.lua:451 0.0%/62.8%
20220701 15:00:59.012 DEBUG  audio.decode - Playback.lua:451 0.0%/52.0%
20220701 15:01:00.093 DEBUG  audio.decode - Playback.lua:451 0.0%/41.2%
20220701 15:01:01.127 DEBUG  audio.decode - Playback.lua:451 0.0%/30.9%
20220701 15:01:02.211 DEBUG  audio.decode - Playback.lua:451 0.0%/20.1%
20220701 15:01:03.332 DEBUG  audio.decode - Playback.lua:451 0.0%/8.8%
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
20220701 15:01:04.232 DEBUG  audio.decode - decode_pause_audio:621 decode_pause_audio interval_ms=0
20220701 15:01:04.232 DEBUG  audio.decode - decode_pause_audio_handler:152 decode_pause_handler interval=0
20220701 15:01:04.232 DEBUG  audio.output - decode_alsa_pause:79 decode_alsa_pause
20220701 15:01:04.232 DEBUG  audio.decode - decode_pause_audio_handler:167 pause_audio decode state: 1 audio state 2
20220701 15:01:04.233 DEBUG  audio.decode - Playback.lua:858 strm p
20220701 15:01:04.233 DEBUG  audio.decode - Playback.lua:1265 stopping local pause timer
20220701 15:01:04.233 DEBUG  audio.decode - decode_pause_audio:621 decode_pause_audio interval_ms=0
20220701 15:01:04.233 DEBUG  audio.decode - decode_pause_audio_handler:152 decode_pause_handler interval=0
20220701 15:01:04.233 DEBUG  audio.decode - decode_pause_audio_handler:167 pause_audio decode state: 1 audio state 2
20220701 15:01:35.062 DEBUG  audio.decode - Playback.lua:858 strm q
20220701 15:01:35.062 DEBUG  audio.decode - Playback.lua:1265 stopping local pause timer
20220701 15:01:35.062 DEBUG  audio.decode - decode_stop:664 decode_stop
20220701 15:01:35.062 DEBUG  audio.decode - Playback.lua:194 source=off
20220701 15:01:35.062 DEBUG  audio.decode - decode_stop_handler:190 decode_stop_handler
20220701 15:01:35.062 DEBUG  audio.codec - decode_mad_stop:548 decode_mad_stop()
20220701 15:01:35.062 DEBUG  audio.output - decode_alsa_stop:88 decode_alsa_stop
20220701 15:01:35.062 DEBUG  audio.decode - Playback.lua:754 disconnect streambuf
20220701 15:01:35.628 DEBUG  audio.decode - Playback.lua:1265 stopping local pause timer
20220701 15:01:35.628 DEBUG  audio.decode - Playback.lua:1195 gainL, gainR: 120 120
20220701 15:01:35.629 DEBUG  audio.decode - Playback.lua:858 strm s
20220701 15:01:35.629 DEBUG  audio.decode - Playback.lua:747 flush streambuf
20220701 15:01:35.629 DEBUG  audio.decode - decode_start:702 decode_start
20220701 15:01:35.629 INFO   audio.decode - Playback.lua:480 connect 192.168.0.126:9000 GET /stream.mp3?player=e0:3f:49:46:08:03 HTTP/1.0
20220701 15:01:35.629 DEBUG  audio.decode - Playback.lua:194 source=stream
20220701 15:01:35.629 INFO   audio.decode - decode_start_handler:277 init decoder mp3
20220701 15:01:35.629 DEBUG  audio.decode - stream_connectL:506 streambuf connect 192.168.0.126:9000
20220701 15:01:35.629 DEBUG  audio.decode - decode_output_set_track_gain:517 Track gain 65536
20220701 15:01:35.629 DEBUG  audio.decode - decode_output_set_track_gain:521 Track clip range 7fffffff 80000000
20220701 15:01:35.629 DEBUG  audio.decode - decode_set_track_polarity_inversion:526 Polarity inversion 0
20220701 15:01:35.629 DEBUG  audio.decode - decode_set_output_channels:534 Output channels left 0, right 0
20220701 15:01:35.629 DEBUG  audio.codec - decode_mad_start:520 decode_mad_start()
20220701 15:01:35.629 DEBUG  audio.output - decode_alsa_start:59 decode_alsa_start
20220701 15:01:35.629 DEBUG  audio.decode - Playback.lua:1265 stopping local pause timer
20220701 15:01:35.629 DEBUG  audio.decode - Playback.lua:1195 gainL, gainR: 120 120
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%
20220701 15:01:36.903 DEBUG  audio.decode - Playback.lua:451 1.0%/99.9%
20220701 15:01:37.037 DEBUG  audio.decode - Playback.lua:424 resume audio bytesReceivedL=256768 outputTime=13771 threshold=245760
20220701 15:01:37.037 DEBUG  audio.decode - decode_resume_audio:598 decode_resume_audio start_jiffies=0
20220701 15:01:37.038 DEBUG  audio.decode - decode_resume_audio_handler:129 decode_resume_audio_handler start_jiffies=0
20220701 15:01:37.038 DEBUG  audio.decode - debug_fullness:108 fullness: 90150 / 3525496 | 2.87% / 99.93%
20220701 15:01:37.038 DEBUG  audio.output - decode_alsa_resume:70 decode_alsa_resume
20220701 15:01:37.038 DEBUG  audio.decode - decode_resume_audio_handler:142 resume_audio decode state: 1 audio state 40
20220701 15:01:37.041 DEBUG  playback_callback:560 playback started, copyright not asserted
20220701 15:01:37.041 DEBUG  pcm_open:840 PCM Open 1 default
20220701 15:01:37.087 ERROR  _pcm_open:721 Access type not available: Invalid argument
20220701 15:01:37.088 WARN   pcm_open:852 PCM Open with mmap failed trying to continue,Invalid argument

20220701 15:01:37.088 DEBUG  pcm_open:854 PCM Open NOMMAP 60BCE0 default
20220701 15:01:37.088 ERROR  pcm_close:607 snd_pcm_drain error: Input/output error
20220701 15:01:37.089 INFO   _pcm_open:729 Opened device default using format: S16_LE sample rate: 32000
20220701 15:01:37.089 INFO   _pcm_open:755 Using buffer period count: 3
20220701 15:01:37.089 INFO   _pcm_open:767 Using buffer time: 30000
ALSA <-> PulseAudio PCM I/O Plugin
Its setup is:
  stream       : PLAYBACK
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 32000
  exact rate   : 32000 (32000/1)
  msbits       : 16
  buffer_size  : 960
  period_size  : 320
  period_time  : 10000
  tstamp_mode  : NONE
  tstamp_type  : GETTIMEOFDAY
  period_step  : 1
  avail_min    : 320
  period_event : 0
  start_threshold  : 1
  stop_threshold   : 960
  silence_threshold: 0
  silence_size : 0
  boundary     : 8646911284551352320
20220701 15:01:37.091 WARN   audio_thread_execute:1048 xrun (avail_update)
20220701 15:01:37.093 ERROR  audio_thread_execute:1081 snd_pcm_start error: File descriptor in bad state
20220701 15:01:37.127 DEBUG  audio.decode - Playback.lua:381 status TRACK STARTED (elapsed: 85)
20220701 15:01:37.160 DEBUG  net.http - SocketHttp.lua:805 SocketHttp {minitower_Chunked}:t_rcvResponse.pump(jive-htt

[Paul Webster]

"Cherry Red" is a record label and I think they provide a show that is dropped in to their schedule.

[slartibartfast]

Looks like the 4pm stop was due to a bad ID and sample rate change.

20220701 15:04:48.333 DEBUG  audio.decode - Playback.lua:451 4.3%/99.8%
20220701 15:04:49.412 DEBUG  audio.decode - Playback.lua:451 7.7%/99.6%
20220701 15:04:50.538 DEBUG  audio.decode - Playback.lua:451 10.4%/99.5%
20220701 15:04:50.786 DEBUG  audio.codec - decode_mad_output:386 Sample rate changed from 32000 to 44100, discarding PCM
20220701 15:04:50.810 DEBUG  audio.decode - Playback.lua:320 status DECODE UNDERRUN
20220701 15:04:50.810 DEBUG  audio.decode - decode_song_ended:774 decode_song_ended
20220701 15:04:50.810 DEBUG  audio.decode - decode_song_ended_handler:319 decode_song_ended_handler
20220701 15:04:50.810 DEBUG  audio.codec - decode_mad_stop:548 decode_mad_stop()
20220701 15:04:51.932 DEBUG  audio.decode - Playback.lua:451 12.5%/91.2%

[22-07-01 14:01:27.3025] Slim::Player::Protocols::HTTP::readMetaData (238) Metadata: StreamTitle='Cherry Red Records - Cherry Red Radio 7, from the 2020 album `Cherry Red Radio`';
[22-07-01 14:01:27.3030] Slim::Player::Protocols::HTTP::parseMetadata (286) Icy metadata received: StreamTitle='Cherry Red Records - Cherry Red Radio 7, from the 2020 album `Cherry Red Radio`';

[22-07-01 16:00:36.7737] Slim::Player::Protocols::HTTP::readMetaData (212) Metadata size: 64
[22-07-01 16:00:36.7743] Slim::Player::Protocols::HTTP::readMetaData (238) Metadata: StreamTitle='Delicious Agony - Delicious Agony ID #9';
[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

I'm logging player.source, player.streaming, player.streaming.remote to INFO

Squeezeplay is 1 hour off for some reason.

The sample rate changed from 32kHz to 44.1kHz which is odd.

[bpa]

The sample rate changed from 32kHz to 44.1kHz which is odd.

My reading.

The problem started with "Cherry Red" which was 44.1kHz.
When player restarted it started playing the "Delicious Agony - Delicious Agony ID #9' which was 32kHz.
Then a normal track was lined up which was 44.1khz - so player then complained changed form 32kHz to 44.1kHz

Usually we see the other way round because player is more likely to have started playing a 44.1kHz track than a 32Khz Station ID - this time timing was different.

That explains the 16:04 - but I don't know what happened at 16:01 (or 15:01 on Squeezeplay log) - is there an issues about the end of long track ? Cherry Red started at 14:00 - so 2hrs long.

[slartibartfast]

My reading.

The problem started with "Cherry Red" which was 44.1kHz.
When player restarted it started playing the "Delicious Agony - Delicious Agony ID #9' which was 32kHz.
Then a normal track was lined up which was 44.1khz - so player then complained changed form 32kHz to 44.1kHz

Usually we see the other way round because player is more likely to have started playing a 44.1kHz track than a 32Khz Station ID - this time timing was different.

That explains the 16:04 - but I don't know what happened at 16:01 (or 15:01 on Squeezeplay log) - is there an issues about the end of long track ? Cherry Red started at 14:00 - so 2hrs long.

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

Sent from my Pixel 3a using Tapatalk

[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%