Announcement

Collapse
No announcement yet.

Radio station stops playing

Collapse
X
 
  • Filter
  • Time
  • Show
Clear All
new posts

    Originally posted by slartibartfast View Post
    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
    Code:
    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.

    Code:
    [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

    Comment


      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
      Code:
      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%

      Comment

      Working...
      X