Home of the Squeezebox™ & Transporter® network music players.
Page 3 of 14 FirstFirst 1234513 ... LastLast
Results 21 to 30 of 137
  1. #21
    Senior Member
    Join Date
    Jan 2010
    Location
    Hertfordshire
    Posts
    9,628
    Quote Originally Posted by bpa View Post
    Playing "direct" on Radio

    I got another rebuffer near track transition, underrun where the stream sends NO data and so connection has to be remade - like following scenario

    The other stop audio situation is logged as follows. It is where LMS thinks the stream has ended ( Streaming -> PlayerReadytoStream) and wants to go onto "NextIfMore" - and there is no more so stop. Need to look around to see if cause of stop can be better determined.
    Code:
    [22-06-21 17:21:07.5761] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:a4:99: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync
    [22-06-21 17:21:08.5827] Slim::Player::StreamingController::playerReadyToStream (2240) 00:04:20:27:a4:99
    [22-06-21 17:21:08.5833] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:a4:99: ReadyToStream in PLAYING-STREAMING -> Slim::Player::StreamingController::_NextIfMore
    [22-06-21 17:21:08.5837] Slim::Player::StreamingController::_setStreamingState (2408) new streaming state IDLE
    [22-06-21 17:21:08.5842] Slim::Player::StreamingController::nextsong (907) The next song is number 0, was 0
    If it makes any difference I have persistent mode streaming for http(s) in network settings.

    Sent from my Pixel 3a using Tapatalk

  2. #22
    Senior Member
    Join Date
    Jan 2010
    Location
    Hertfordshire
    Posts
    9,628
    Quote Originally Posted by bpa View Post
    I can't be sure but the the messages look as if player is using proxied and woudl explain the "socket" message.

    I moved onto just player.source logging as I think at end of a track, the stream is sending chunks with zero bytes which LMS interprets as "end of stream" and so looks for next entry in playlist. The "repeat " setting may fix it.

    Also the stream behaviours may has changed since my testing earlier as if earlier it was one big pre-recorded session and now the stream is more fragmented. I've seen similar with US station where more ads/breaks during normal hours.
    Another log with player.source set to debug. I don't know why it tries to find Lame.
    Attached Files Attached Files

  3. #23
    Senior Member
    Join Date
    Oct 2005
    Location
    Ireland
    Posts
    21,883
    Quote Originally Posted by slartibartfast View Post
    Another log with player.source set to debug.
    Same issue as I see - "playerReadyToStream" - AFAICT this is due to a STMd from player - I need find out what condition STMd is sent.
    Code:
    [22-06-21 17:42:57.6817] Slim::Player::StreamingController::playerReadyToStream (2219) Touch
    [22-06-21 17:42:57.6826] Slim::Player::StreamingController::_eventAction (272) Touch: ReadyToStream in PLAYING-STREAMING -> Slim::Player::StreamingController::_NextIfMore
    [22-06-21 17:42:57.6834] Slim::Player::StreamingController::_setStreamingState (2387) new streaming state IDLE
    [22-06-21 17:42:57.6844] Slim::Player::StreamingController::nextsong (889) The next song is number 0, was 0
    
    .
    .
    .
    [22-06-21 17:43:07.6542] Slim::Player::StreamingController::playerStopped (2178) Touch
    [22-06-21 17:43:07.6549] Slim::Player::StreamingController::_eventAction (272) Touch: Stopped in PLAYING-IDLE -> Slim::Player::StreamingController::_Stopped
    [22-06-21 17:43:07.6555] Slim::Player::StreamingController::_setPlayingState (2378) new playing state STOPPED
    [22-06-21 17:43:07.6562] Slim::Player::StreamingController::_eventAction (302) Touch: Stopped - new state STOPPED-IDLE
    [22-06-21 17:43:08.0208] Slim::Player::StreamingController::playerEndOfStream (2287) Touch
    [22-06-21 17:43:08.0218] Slim::Player::StreamingController::_eventAction (272) Touch: EndOfStream in STOPPED-IDLE -> Slim::Player::StreamingController::_NoOp
    I don't know why it tries to find Lame.
    Normal LMS. All conversion rules are evaluated in parallel and then "best" one is chosen. LAME conversion to Flac/PCM is in some of the rules. Best rule is "native".

  4. #24
    Senior Member
    Join Date
    Jan 2010
    Location
    Hertfordshire
    Posts
    9,628
    Quote Originally Posted by bpa View Post
    Same issue as I see - "playerReadyToStream" - AFAICT this is due to a STMd from player - I need find out what condition STMd is sent.
    Code:
    [22-06-21 17:42:57.6817] Slim::Player::StreamingController::playerReadyToStream (2219) Touch
    [22-06-21 17:42:57.6826] Slim::Player::StreamingController::_eventAction (272) Touch: ReadyToStream in PLAYING-STREAMING -> Slim::Player::StreamingController::_NextIfMore
    [22-06-21 17:42:57.6834] Slim::Player::StreamingController::_setStreamingState (2387) new streaming state IDLE
    [22-06-21 17:42:57.6844] Slim::Player::StreamingController::nextsong (889) The next song is number 0, was 0
    
    .
    .
    .
    [22-06-21 17:43:07.6542] Slim::Player::StreamingController::playerStopped (2178) Touch
    [22-06-21 17:43:07.6549] Slim::Player::StreamingController::_eventAction (272) Touch: Stopped in PLAYING-IDLE -> Slim::Player::StreamingController::_Stopped
    [22-06-21 17:43:07.6555] Slim::Player::StreamingController::_setPlayingState (2378) new playing state STOPPED
    [22-06-21 17:43:07.6562] Slim::Player::StreamingController::_eventAction (302) Touch: Stopped - new state STOPPED-IDLE
    [22-06-21 17:43:08.0208] Slim::Player::StreamingController::playerEndOfStream (2287) Touch
    [22-06-21 17:43:08.0218] Slim::Player::StreamingController::_eventAction (272) Touch: EndOfStream in STOPPED-IDLE -> Slim::Player::StreamingController::_NoOp

    Normal LMS. All conversion rules are evaluated in parallel and then "best" one is chosen. LAME conversion to Flac/PCM is in some of the rules. Best rule is "native".
    I tried setting "Repeat" on the Touch and played both Touch and Radio. The Radio stopped at around 20.14 and you can see the Touch restarting at that time and again a little while later at 20.37.
    Not ideal but until we find a proper solution "Repeat" works.

    Code:
    [22-06-21 20:13:21.5585] Slim::Player::Protocols::HTTP::readMetaData (205) Metadata byte not read, trying again: Resource temporarily unavailable
    [22-06-21 20:13:29.8410] Slim::Player::Protocols::HTTP::readMetaData (212) Metadata size: 80
    [22-06-21 20:13:29.8420] Slim::Player::Protocols::HTTP::readMetaData (238) Metadata: StreamTitle='Curved Air - It Happened Today, from the 1990 album `Alive 1990`';
    [22-06-21 20:13:29.8442] Slim::Player::Protocols::HTTP::parseMetadata (270) Trying metadata parser Plugins::RadioNowPlaying::Plugin::parser
    [22-06-21 20:13:29.8640] Slim::Player::Protocols::HTTP::readMetaData (212) Metadata size: 80
    [22-06-21 20:13:29.8648] Slim::Player::Protocols::HTTP::readMetaData (238) Metadata: StreamTitle='Curved Air - It Happened Today, from the 1990 album `Alive 1990`';
    [22-06-21 20:13:29.8670] Slim::Player::Protocols::HTTP::parseMetadata (270) Trying metadata parser Plugins::RadioNowPlaying::Plugin::parser
    [22-06-21 20:13:29.9220] Slim::Player::Protocols::HTTP::readMetaData (205) Metadata byte not read, trying again: Resource temporarily unavailable
    [22-06-21 20:14:01.0131] Slim::Formats::RemoteStream::DESTROY (339) Slim::Player::Protocols::HTTP - in DESTROY
    [22-06-21 20:14:01.0139] Slim::Formats::RemoteStream::DESTROY (340) Slim::Player::Protocols::HTTP About to close socket to: [http://deliciousagony.streamguys1.com/]
    [22-06-21 20:14:01.0202] Slim::Formats::RemoteStream::new (69) Opening connection to http://deliciousagony.streamguys1.com/: [deliciousagony.streamguys1.com on port 80 with path / with timeout 15]
    [22-06-21 20:14:01.1480] 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; armv7l-linux; EN_GB; utf8) SqueezeCenter, Squeezebox Server, Logitech Media Server/8.3.0/1654547000
    Icy-MetaData: 1
    
    [22-06-21 20:14:01.2551] Slim::Formats::RemoteStream::request (151) Response: HTTP/1.0 200 OK
    [22-06-21 20:14:01.2675] Slim::Player::Protocols::HTTP::parseHeaders (818) Setting new title for http://deliciousagony.streamguys1.com/, Delicious Agony
    [22-06-21 20:14:01.2709] Slim::Player::Protocols::HTTP::response (118) Using Persistent service for http://deliciousagony.streamguys1.com/
    [22-06-21 20:14:01.2717] Slim::Formats::RemoteStream::request (217) Opened stream!
    [22-06-21 20:14:01.4590] Slim::Player::Protocols::HTTP::readMetaData (212) Metadata size: 80
    [22-06-21 20:14:01.4596] Slim::Player::Protocols::HTTP::readMetaData (238) Metadata: StreamTitle='Curved Air - It Happened Today, from the 1990 album `Alive 1990`';
    [22-06-21 20:14:01.4610] Slim::Player::Protocols::HTTP::parseMetadata (270) Trying metadata parser Plugins::RadioNowPlaying::Plugin::parser
    
    [22-06-21 20:18:23.5373] Slim::Player::Protocols::HTTP::readMetaData (205) Metadata byte not read, trying again: Resource temporarily unavailable
    [22-06-21 20:18:56.4036] Slim::Player::Protocols::HTTP::readMetaData (212) Metadata size: 96
    [22-06-21 20:18:56.4044] Slim::Player::Protocols::HTTP::readMetaData (238) Metadata: StreamTitle='Roxy Music - A Song For Europe, from the 1990 album `Heart Still Beating`';
    [22-06-21 20:18:56.4066] Slim::Player::Protocols::HTTP::parseMetadata (270) Trying metadata parser Plugins::RadioNowPlaying::Plugin::parser
    [22-06-21 20:19:35.0197] Slim::Player::Protocols::HTTP::readMetaData (205) Metadata byte not read, trying again: Resource temporarily unavailable
    [22-06-21 20:21:01.0243] Slim::Player::Protocols::HTTP::readMetaData (205) Metadata byte not read, trying again: Resource temporarily unavailable
    [22-06-21 20:21:43.0567] Slim::Player::Protocols::HTTP::readMetaData (205) Metadata byte not read, trying again: Resource temporarily unavailable
    [22-06-21 20:22:47.0153] Slim::Player::Protocols::HTTP::readMetaData (205) Metadata byte not read, trying again: Resource temporarily unavailable
    [22-06-21 20:24:54.8682] Slim::Player::Protocols::HTTP::readMetaData (205) Metadata byte not read, trying again: Resource temporarily unavailable
    [22-06-21 20:25:18.6304] Slim::Player::Protocols::HTTP::readMetaData (212) Metadata size: 80
    [22-06-21 20:25:18.6313] Slim::Player::Protocols::HTTP::readMetaData (238) Metadata: StreamTitle='Joe Mallon - Shadow & Light Hillage 6/9/20 Voiceover 2';
    [22-06-21 20:25:18.6336] Slim::Player::Protocols::HTTP::parseMetadata (270) Trying metadata parser Plugins::RadioNowPlaying::Plugin::parser
    [22-06-21 20:26:38.6260] Slim::Player::Protocols::HTTP::readMetaData (205) Metadata byte not read, trying again: Resource temporarily unavailable
    [22-06-21 20:26:46.9525] Slim::Player::Protocols::HTTP::readMetaData (212) Metadata size: 80
    [22-06-21 20:26:46.9534] Slim::Player::Protocols::HTTP::readMetaData (238) Metadata: StreamTitle='Pink Floyd - Sorrow, from the 1990 album `Knebworth`';
    [22-06-21 20:26:46.9558] Slim::Player::Protocols::HTTP::parseMetadata (270) Trying metadata parser Plugins::RadioNowPlaying::Plugin::parser
    [22-06-21 20:30:04.8371] Slim::Player::Protocols::HTTP::readMetaData (205) Metadata byte not read, trying again: Resource temporarily unavailable
    [22-06-21 20:31:52.2653] Slim::Player::Protocols::HTTP::readMetaData (205) Metadata byte not read, trying again: Resource temporarily unavailable
    [22-06-21 20:33:16.1056] Slim::Player::Protocols::HTTP::readMetaData (205) Metadata byte not read, trying again: Resource temporarily unavailable
    [22-06-21 20:35:48.1111] Slim::Player::Protocols::HTTP::readMetaData (205) Metadata byte not read, trying again: Resource temporarily unavailable
    [22-06-21 20:37:11.1385] Slim::Formats::RemoteStream::DESTROY (339) Slim::Player::Protocols::HTTP - in DESTROY
    [22-06-21 20:37:11.1393] Slim::Formats::RemoteStream::DESTROY (340) Slim::Player::Protocols::HTTP About to close socket to: [http://deliciousagony.streamguys1.com/]
    [22-06-21 20:37:11.1448] Slim::Formats::RemoteStream::new (69) Opening connection to http://deliciousagony.streamguys1.com/: [deliciousagony.streamguys1.com on port 80 with path / with timeout 15]
    [22-06-21 20:37:11.3539] 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; armv7l-linux; EN_GB; utf8) SqueezeCenter, Squeezebox Server, Logitech Media Server/8.3.0/1654547000
    Icy-MetaData: 1
    
    [22-06-21 20:37:11.4517] Slim::Formats::RemoteStream::request (151) Response: HTTP/1.0 200 OK
    [22-06-21 20:37:11.4635] Slim::Player::Protocols::HTTP::parseHeaders (818) Setting new title for http://deliciousagony.streamguys1.com/, Delicious Agony
    [22-06-21 20:37:11.4669] Slim::Player::Protocols::HTTP::response (118) Using Persistent service for http://deliciousagony.streamguys1.com/
    [22-06-21 20:37:11.4676] Slim::Formats::RemoteStream::request (217) Opened stream!
    [22-06-21 20:37:11.6602] Slim::Player::Protocols::HTTP::readMetaData (212) Metadata size: 80
    [22-06-21 20:37:11.6610] Slim::Player::Protocols::HTTP::readMetaData (238) Metadata: StreamTitle='Pink Floyd - Sorrow, from the 1990 album `Knebworth`';
    [22-06-21 20:37:11.6630] Slim::Player::Protocols::HTTP::parseMetadata (270) Trying metadata parser Plugins::RadioNowPlaying::Plugin::parser
    [22-06-21 20:37:12.0787] Slim::Player::Protocols::HTTP::readMetaData (205) Metadata byte not read, trying again: Resource temporarily unavailable

  5. #25
    Senior Member
    Join Date
    Oct 2005
    Location
    Ireland
    Posts
    21,883
    Quote Originally Posted by slartibartfast View Post
    I tried setting "Repeat" on the Touch and played both Touch and Radio. The Radio stopped at around 20.14 and you can see the Touch restarting at that time and again a little while later at 20.37.
    Not ideal but until we find a proper solution "Repeat" works.
    I'm testing "direct" so that LMS is not a factor.

    I had a squeezelite instance and a Radio playing at the same time.

    I had one rebuffer incident - it affected both players and both managed to get going again although it took Radio a bit longer.

    A while later - Radio stopped, squeezelite was OK and judging by squeezelite metadata - there was a track change about then.

    So it looks like a Radio/Touch player code issue, not LMS and not Squeezlite (so bridge plugins will work) - maybe enable Radio logging next. A Wireshark log may also be useful.

  6. #26
    Senior Member
    Join Date
    Jan 2010
    Location
    Hertfordshire
    Posts
    9,628
    Quote Originally Posted by bpa View Post
    I'm testing "direct" so that LMS is not a factor.

    I had a squeezelite instance and a Radio playing at the same time.

    I had one rebuffer incident - it affected both players and both managed to get going again although it took Radio a bit longer.

    A while later - Radio stopped, squeezelite was OK and judging by squeezelite metadata - there was a track change about then.

    So it looks like a Radio/Touch player code issue, not LMS and not Squeezlite (so bridge plugins will work) - maybe enable Radio logging next. A Wireshark log may also be useful.
    Squeezeplay probably has the same issue as the Radio with the same logging available. I've installed Wireshark before and didn't have a clue how to use it.

    Sent from my Pixel 3a using Tapatalk

  7. #27
    Senior Member
    Join Date
    Jan 2010
    Location
    Hertfordshire
    Posts
    9,628
    Quote Originally Posted by bpa View Post
    I'm testing "direct" so that LMS is not a factor.

    I had a squeezelite instance and a Radio playing at the same time.

    I had one rebuffer incident - it affected both players and both managed to get going again although it took Radio a bit longer.

    A while later - Radio stopped, squeezelite was OK and judging by squeezelite metadata - there was a track change about then.

    So it looks like a Radio/Touch player code issue, not LMS and not Squeezlite (so bridge plugins will work) - maybe enable Radio logging next. A Wireshark log may also be useful.
    Which log would you use on the Radio and Squeezeplay?

    Sent from my Pixel 3a using Tapatalk

  8. #28
    Senior Member
    Join Date
    Oct 2005
    Location
    Ireland
    Posts
    21,883
    Quote Originally Posted by slartibartfast View Post
    Which log would you use on the Radio and Squeezeplay?
    audio.decode to DEBUG - will show metadata and the HTTP/GET to start playing.

    I've started a Squeezplay session instead of squeezelite. So far only a rebuffering event.

    edit:

    net.http - if you want some http audio chunk details.

  9. #29
    Senior Member
    Join Date
    Oct 2005
    Location
    Ireland
    Posts
    21,883
    Have been playing the station direct on radio with Radio logging - for a number of hours yesterday evening and since 800am this morning. Only rebuffer events have occurred.

    I "feel" the problem occurred more during afternoon when the programming is shorter and maybe less preprogrammed and more program ID's. So perhaps problems are due to gaps when presenter is changing tracks manually.

    The regular log audio.decode entry has changed - not sure what the number mean nor any significance - I assume it is some sort of buffer fullness measure.

    Code:
    Jun 22 08:46:17 squeezeplay: INFO   audio.decode - Playback.lua:448 1.0%/99.7%
    Jun 22 08:46:18 squeezeplay: INFO   audio.decode - Playback.lua:448 1.0%/99.4%
    .
    .
    .
    Jun 22 11:08:23 squeezeplay: INFO   audio.decode - Playback.lua:448 26.8%/99.8%
    Jun 22 11:08:24 squeezeplay: INFO   audio.decode - Playback.lua:448 26.9%/99.8%

  10. #30
    Senior Member
    Join Date
    Jan 2010
    Location
    Hertfordshire
    Posts
    9,628
    Quote Originally Posted by bpa View Post
    Have been playing the station direct on radio with Radio logging - for a number of hours yesterday evening and since 800am this morning. Only rebuffer events have occurred.

    I "feel" the problem occurred more during afternoon when the programming is shorter and maybe less preprogrammed and more program ID's. So perhaps problems are due to gaps when presenter is changing tracks manually.

    The regular log audio.decode entry has changed - not sure what the number mean nor any significance - I assume it is some sort of buffer fullness measure.

    Code:
    Jun 22 08:46:17 squeezeplay: INFO   audio.decode - Playback.lua:448 1.0%/99.7%
    Jun 22 08:46:18 squeezeplay: INFO   audio.decode - Playback.lua:448 1.0%/99.4%
    .
    .
    .
    Jun 22 11:08:23 squeezeplay: INFO   audio.decode - Playback.lua:448 26.8%/99.8%
    Jun 22 11:08:24 squeezeplay: INFO   audio.decode - Playback.lua:448 26.9%/99.8%
    I've been playing on Squeezeplay for more than an hour and haven't seen any Station ID events yet.

    Sent from my Pixel 3a using Tapatalk

Posting Permissions

  • You may not post new threads
  • You may not post replies
  • You may not post attachments
  • You may not edit your posts
  •