Home of the Squeezebox™ & Transporter® network music players.
Page 1 of 2 12 LastLast
Results 1 to 10 of 18
  1. #1
    Senior Member chaug's Avatar
    Join Date
    Jun 2011
    Posts
    103

    Radio stops playing after about 15 minutes, then plays fine (logs included)

    My daughters SB Radio keeps stopping about 15 minutes into the playlist. Once we press play again after that first stop, it plays as it should until it powers off automatically after an hour (power save setting). It's really annoying and I can't figure out what is causing this behaviour.

    The SB Radio is known for its wifi connectivity issues so the first thing I did was connect it to the ethernet and I was so sure that would solve it. But it didn't. I looked at the logs but couldn't see anything. I changed the log level for some of the logging categories (but there are so many and I'm not sure exactly which ones to target. Besides, the log settings behave erratically. Sometimes they are not saved and some are displayed as saved but actuall log behyaviour does not seem to correspond to that. But I may be wrong on that.) Anyway, today I was finally able to capture the event on the log:

    Code:
    [20-10-26 22:01:03.6015] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync
    [20-10-26 22:01:04.7215] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync
    [20-10-26 22:01:05.0117] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync
    [20-10-26 22:01:05.8110] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync
    [20-10-26 22:01:06.9911] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync
    [20-10-26 22:01:08.0119] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync
    [20-10-26 22:01:09.0509] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync
    [20-10-26 22:01:09.0971] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync
    [20-10-26 22:01:10.2127] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PLAYING-STREAMING -> Slim::Player::StreamingController::_CheckSync
    [20-10-26 22:01:11.0015] Slim::Player::StreamingController::pause (2136) 00:04:20:27:da:2d
    [20-10-26 22:01:11.0016] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: Pause in PLAYING-STREAMING -> Slim::Player::StreamingController::_Pause
    [20-10-26 22:01:11.0018] Slim::Player::StreamingController::_setPlayingState (2377) new playing state PAUSED
    [20-10-26 22:01:11.0022] Slim::Player::StreamingController::_eventAction (302) 00:04:20:27:da:2d: Pause - new state PAUSED-STREAMING
    [20-10-26 22:01:11.0025] Slim::Player::Source::playmode (95) 00:04:20:27:da:2d: Current playmode: pause
    [20-10-26 22:01:11.0503] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PAUSED-STREAMING -> Slim::Player::StreamingController::_CheckPaused
    [20-10-26 22:01:11.0762] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PAUSED-STREAMING -> Slim::Player::StreamingController::_CheckPaused
    [20-10-26 22:01:11.0852] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PAUSED-STREAMING -> Slim::Player::StreamingController::_CheckPaused
    [20-10-26 22:01:11.2916] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PAUSED-STREAMING -> Slim::Player::StreamingController::_CheckPaused
    [20-10-26 22:01:12.3623] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PAUSED-STREAMING -> Slim::Player::StreamingController::_CheckPaused
    [20-10-26 22:01:13.0507] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PAUSED-STREAMING -> Slim::Player::StreamingController::_CheckPaused
    [20-10-26 22:01:13.4122] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PAUSED-STREAMING -> Slim::Player::StreamingController::_CheckPaused
    [20-10-26 22:01:14.5437] Slim::Player::StreamingController::_eventAction (272) 00:04:20:27:da:2d: StatusHeartbeat in PAUSED-STREAMING -> Slim::Player::StreamingController::_CheckPaused
    Could someone assist me in interpreting these? I can see that it switched to pause but does it say why? (I can say with absolute certainty that no button was pressed by a human, neither physically or virtually).

    This log was with logging for player.streaming set to warn. I increased it to debug, hoping to get more info next time. But maybe there are other logs where I should increase the log level?
    Server: LMS 8.1.1 on an Ubuntu 18.04 virtual machine
    Players: Radio, Touch, Duet (Receiver & Controller), 2 Booms
    Remote control apps: Material Skin (Web UI), but also SqueezePad (iOS), Squeezecontroller (Android)
    Important plugins: Trackstat, Spicefly Sugarcube, Lazy Search Music, Custom Browse, Multi Library

  2. #2
    Senior Member chaug's Avatar
    Join Date
    Jun 2011
    Posts
    103
    So here is a new failure event, this time with debug logging, as described in the previous post. Strangely, the word STOP comes up multiple times, but the player actually only stopped once and that was at 22:11:10. It only took me a couple of seconds to press play again at 22:11:28.

    Code:
    [20-10-28 22:01:00.6220] Slim::Player::StreamingController::_Stream (1213) 00:04:20:27:da:2d: preparing to stream song index 8
    [20-10-28 22:01:00.6221] Slim::Player::Song::open (363) file:///c/media/Music/c/Wolfgang%20Amadeus%20Mozart/Coronation%20Mass%20[Hinreiner]/04%20Wolfgang%20Amadeus%20Mozart%20-%20Motette%20%27Exsultate%20Jubilate%27%20F-DUR%20KV%20165.flac
    [20-10-28 22:01:00.6226] Slim::Player::TranscodingHelper::getConvertCommand2 (445) Matched: flc->flc via: -
    [20-10-28 22:01:00.6227] Slim::Player::Song::open (387) seek=false time=0 canSeek=1
    [20-10-28 22:01:00.6230] Slim::Player::TranscodingHelper::getConvertCommand2 (445) Matched: flc->flc via: -
    [20-10-28 22:01:00.6231] Slim::Player::Song::open (408) Transcoder: streamMode=I, streamformat=flc
    [20-10-28 22:01:00.6232] Slim::Player::Song::open (462) Opening stream (no direct streaming) using Slim::Player::Protocols::File [file:///c/media/Music/c/Wolfgang%20Amadeus%20Mozart/Coronation%20Mass%20[Hinreiner]/04%20Wolfgang%20Amadeus%20Mozart%20-%20Motette%20%27Exsultate%20Jubilate%27%20F-DUR%20KV%20165.flac]
    [20-10-28 22:01:00.6234] Slim::Player::Protocols::File::open (80) duration: [933] size: [70864241] endian [] offset: [0] for file:///c/media/Music/c/Wolfgang%20Amadeus%20Mozart/Coronation%20Mass%20[Hinreiner]/04%20Wolfgang%20Amadeus%20Mozart%20-%20Motette%20%27Exsultate%20Jubilate%27%20F-DUR%20KV%20165.flac
    [20-10-28 22:01:00.6235] Slim::Player::Protocols::File::open (97) Opening file /c/media/Music/c/Wolfgang Amadeus Mozart/Coronation Mass [Hinreiner]/04 Wolfgang Amadeus Mozart - Motette 'Exsultate Jubilate' F-DUR KV 165.flac
    [20-10-28 22:01:00.6242] Slim::Player::Protocols::File::open (191) Seeking in 0 into /c/media/Music/c/Wolfgang Amadeus Mozart/Coronation Mass [Hinreiner]/04 Wolfgang Amadeus Mozart - Motette 'Exsultate Jubilate' F-DUR KV 165.flac
    [20-10-28 22:01:00.6245] Slim::Player::Song::open (483) URL is a song (audio): file:///c/media/Music/c/Wolfgang%20Amadeus%20Mozart/Coronation%20Mass%20[Hinreiner]/04%20Wolfgang%20Amadeus%20Mozart%20-%20Motette%20%27Exsultate%20Jubilate%27%20F-DUR%20KV%20165.flac, type=flc
    [20-10-28 22:01:00.6557] Slim::Player::StreamingController::_Stream (1282) 00:04:20:27:da:2d: stream
    [20-10-28 22:01:00.6578] Slim::Player::StreamingController::_Stream (1319) Song queue is now 8,7
    [20-10-28 22:01:00.6579] Slim::Player::StreamingController::_setStreamingState (2386) new streaming state STREAMING
    [20-10-28 22:01:10.0051] Slim::Player::StreamingController::playerTrackStarted (2200) 00:04:20:27:da:2d
    [20-10-28 22:01:10.0054] Slim::Player::StreamingController::_setPlayingState (2377) new playing state PLAYING
    [20-10-28 22:01:10.0055] Slim::Player::StreamingController::_Playing (362) Song 7 is not longer in the queue
    [20-10-28 22:01:10.0056] Slim::Player::StreamingController::_Playing (368) Song 8 has now started playing
    [20-10-28 22:01:10.0060] Slim::Player::StreamingController::_Playing (397) Song queue is now 8
    [20-10-28 22:01:10.4548] Slim::Player::TranscodingHelper::getConvertCommand2 (445) Matched: flc->flc via: -
    [20-10-28 22:11:10.0102] Slim::Player::StreamingController::stop (2117) 00:04:20:27:da:2d
    [20-10-28 22:11:10.0109] Slim::Player::StreamingController::_Stop (610) Song queue is now 8
    [20-10-28 22:11:10.0133] Slim::Player::StreamingController::_setPlayingState (2377) new playing state STOPPED
    [20-10-28 22:11:10.0135] Slim::Player::StreamingController::_setStreamingState (2386) new streaming state IDLE
    [20-10-28 22:11:10.0139] Slim::Player::Source::playmode (95) 00:04:20:27:da:2d: Current playmode: stop
    [20-10-28 22:11:10.5536] Slim::Player::TranscodingHelper::getConvertCommand2 (445) Matched: flc->flc via: -
    [20-10-28 22:11:28.6430] Slim::Player::StreamingController::playerActive (2013) 00:04:20:27:da:2d player already active: 00:04:20:27:da:2d
    [20-10-28 22:11:28.6435] Slim::Player::StreamingController::play (2120) 00:04:20:27:da:2d
    [20-10-28 22:11:28.6439] Slim::Player::StreamingController::_Stop (610) Song queue is now 8
    [20-10-28 22:11:28.6440] Slim::Player::StreamingController::_setPlayingState (2377) new playing state STOPPED
    [20-10-28 22:11:28.6441] Slim::Player::StreamingController::_setStreamingState (2386) new streaming state IDLE
    [20-10-28 22:11:28.6447] Slim::Player::Song::new (107) index 8 -> file:///c/media/Music/c/Wolfgang%20Amadeus%20Mozart/Coronation%20Mass%20[Hinreiner]/04%20Wolfgang%20Amadeus%20Mozart%20-%20Motette%20%27Exsultate%20Jubilate%27%20F-DUR%20KV%20165.flac
    [20-10-28 22:11:28.6449] Slim::Player::StreamingController::_setStreamingState (2386) new streaming state TRACKWAIT
    [20-10-28 22:11:28.6461] Slim::Player::StreamingController::_playersMessage (796) Now Playing: file:///c/media/Music/c/Wolfgang%20Amadeus%20Mozart/Coronation%20Mass%20[Hinreiner]/04%20Wolfgang%20Amadeus%20Mozart%20-%20Motette%20%27Exsultate%20Jubilate%27%20F-DUR%20KV%20165.flac
    [20-10-28 22:11:28.6491] Slim::Player::Song::getNextSong (228) file:///c/media/Music/c/Wolfgang%20Amadeus%20Mozart/Coronation%20Mass%20[Hinreiner]/04%20Wolfgang%20Amadeus%20Mozart%20-%20Motette%20%27Exsultate%20Jubilate%27%20F-DUR%20KV%20165.flac
    [20-10-28 22:11:28.6493] Slim::Player::StreamingController::_nextTrackReady (744) 00:04:20:27:da:2d: nextTrack will be index 8
    [20-10-28 22:11:28.6494] Slim::Player::StreamingController::_Stream (1210) Song queue is now 8
    [20-10-28 22:11:28.6495] Slim::Player::StreamingController::_Stream (1213) 00:04:20:27:da:2d: preparing to stream song index 8
    [20-10-28 22:11:28.6496] Slim::Player::Song::open (363) file:///c/media/Music/c/Wolfgang%20Amadeus%20Mozart/Coronation%20Mass%20[Hinreiner]/04%20Wolfgang%20Amadeus%20Mozart%20-%20Motette%20%27Exsultate%20Jubilate%27%20F-DUR%20KV%20165.flac
    [20-10-28 22:11:28.6501] Slim::Player::TranscodingHelper::getConvertCommand2 (445) Matched: flc->flc via: -
    [20-10-28 22:11:28.6502] Slim::Player::Song::open (387) seek=false time=0 canSeek=1
    [20-10-28 22:11:28.6505] Slim::Player::TranscodingHelper::getConvertCommand2 (445) Matched: flc->flc via: -
    [20-10-28 22:11:28.6506] Slim::Player::Song::open (408) Transcoder: streamMode=I, streamformat=flc
    [20-10-28 22:11:28.6507] Slim::Player::Song::open (462) Opening stream (no direct streaming) using Slim::Player::Protocols::File [file:///c/media/Music/c/Wolfgang%20Amadeus%20Mozart/Coronation%20Mass%20[Hinreiner]/04%20Wolfgang%20Amadeus%20Mozart%20-%20Motette%20%27Exsultate%20Jubilate%27%20F-DUR%20KV%20165.flac]
    [20-10-28 22:11:28.6510] Slim::Player::Protocols::File::open (80) duration: [933] size: [70864241] endian [] offset: [0] for file:///c/media/Music/c/Wolfgang%20Amadeus%20Mozart/Coronation%20Mass%20[Hinreiner]/04%20Wolfgang%20Amadeus%20Mozart%20-%20Motette%20%27Exsultate%20Jubilate%27%20F-DUR%20KV%20165.flac
    [20-10-28 22:11:28.6511] Slim::Player::Protocols::File::open (97) Opening file /c/media/Music/c/Wolfgang Amadeus Mozart/Coronation Mass [Hinreiner]/04 Wolfgang Amadeus Mozart - Motette 'Exsultate Jubilate' F-DUR KV 165.flac
    [20-10-28 22:11:28.6513] Slim::Player::Protocols::File::open (191) Seeking in 0 into /c/media/Music/c/Wolfgang Amadeus Mozart/Coronation Mass [Hinreiner]/04 Wolfgang Amadeus Mozart - Motette 'Exsultate Jubilate' F-DUR KV 165.flac
    [20-10-28 22:11:28.6515] Slim::Player::Song::open (483) URL is a song (audio): file:///c/media/Music/c/Wolfgang%20Amadeus%20Mozart/Coronation%20Mass%20[Hinreiner]/04%20Wolfgang%20Amadeus%20Mozart%20-%20Motette%20%27Exsultate%20Jubilate%27%20F-DUR%20KV%20165.flac, type=flc
    [20-10-28 22:11:28.6877] Slim::Player::StreamingController::_Stream (1282) 00:04:20:27:da:2d: stream
    [20-10-28 22:11:28.6887] Slim::Player::StreamingController::_Stream (1319) Song queue is now 8
    [20-10-28 22:11:28.6890] Slim::Player::StreamingController::_setPlayingState (2377) new playing state BUFFERING
    [20-10-28 22:11:28.6891] Slim::Player::StreamingController::_setStreamingState (2386) new streaming state STREAMING
    [20-10-28 22:11:28.6977] Slim::Player::TranscodingHelper::getConvertCommand2 (445) Matched: flc->flc via: -
    [20-10-28 22:11:30.1574] Slim::Player::StreamingController::playerTrackStarted (2200) 00:04:20:27:da:2d
    [20-10-28 22:11:30.1576] Slim::Player::StreamingController::_setPlayingState (2377) new playing state PLAYING
    [20-10-28 22:11:30.1577] Slim::Player::StreamingController::_Playing (368) Song 8 has now started playing
    [20-10-28 22:11:30.1581] Slim::Player::StreamingController::_Playing (397) Song queue is now 8
    I guess the central log-item is

    Code:
    [20-10-28 22:11:10.0102] Slim::Player::StreamingController::stop (2117) 00:04:20:27:da:2d
    What does the 2117 indicate? It seems to be the only bit of information that could lead us somewhere...
    Server: LMS 8.1.1 on an Ubuntu 18.04 virtual machine
    Players: Radio, Touch, Duet (Receiver & Controller), 2 Booms
    Remote control apps: Material Skin (Web UI), but also SqueezePad (iOS), Squeezecontroller (Android)
    Important plugins: Trackstat, Spicefly Sugarcube, Lazy Search Music, Custom Browse, Multi Library

  3. #3
    Senior Member
    Join Date
    May 2010
    Location
    London, UK
    Posts
    802
    Quote Originally Posted by chaug View Post
    Code:
    [20-10-28 22:11:10.0102] Slim::Player::StreamingController::stop (2117) 00:04:20:27:da:2d
    What does the 2117 indicate? It seems to be the only bit of information that could lead us somewhere...
    The line in the source code that generated the message:

    https://github.com/Logitech/slimserv...oller.pm#L2117

    But I donĺt know why it stopped. And I donĺt know why the previous example paused. Someone else will have a better idea of how to diagnose.

    Have you got the Radio linked or grouped with another player ?

  4. #4
    Senior Member chaug's Avatar
    Join Date
    Jun 2011
    Posts
    103
    Okay, good to know that these are the line numbers and, I suppose, Slim::Player::StreamingController is the path to the file.

    Quote Originally Posted by mrw View Post
    Have you got the Radio linked or grouped with another player ?
    No, the player is not synced to any other player.

    I searched for the word stop in StreamingController.pm in order to find the places rom where that subfunction can be called, but I couldn't figure it out. Perl doesn't seem to be the most readable of programming languages... (or I'm just to dumb).

    What I read here, however, gave me the idea the issue might be related to the autopowersave function, which I have enabled and set to "Power Save always" after 60 minutes. Maybe there is some bug triggering the powersave early? But then again, that would mean the player would go to sleep, which it doesn't. It just stops playing. I now disabled autopowersave to see if the issue disappears.
    Server: LMS 8.1.1 on an Ubuntu 18.04 virtual machine
    Players: Radio, Touch, Duet (Receiver & Controller), 2 Booms
    Remote control apps: Material Skin (Web UI), but also SqueezePad (iOS), Squeezecontroller (Android)
    Important plugins: Trackstat, Spicefly Sugarcube, Lazy Search Music, Custom Browse, Multi Library

  5. #5
    Senior Member
    Join Date
    May 2010
    Location
    London, UK
    Posts
    802
    Quote Originally Posted by chaug View Post
    I searched for the word stop in StreamingController.pm in order to find the places rom where that subfunction can be called, but I couldn't figure it out. Perl doesn't seem to be the most readable of programming languages... (or I'm just to dumb).
    LMS seems to me to be very intricate... not easy to fathom unless you know what's going on.

    Coming from another angle: Do you know when the bad behaviour started, and can you recall any changes to your installation that preceded it ?

  6. #6
    Senior Member jth's Avatar
    Join Date
    Apr 2005
    Location
    Phoenix, AZ, USA
    Posts
    380
    Also, the PowerSave plugin itself can print debug messages to help you determine if it is the problem.

    Server->Logging->Advanced Log Settings->plugin.powersave->debug

  7. #7
    Senior Member
    Join Date
    Oct 2005
    Location
    Ireland
    Posts
    20,418
    LMS has lots of moving parts which mesh. Many function calls are done indirectly or via callbacks - so you won't find the call just by searching source code.

    mrw's advice is good. What's the history ?

    Also I'd consider ssh'ing into the radio, enable some radio logging and then look at the the radio log of event from Ubuntu terminal and see if the "pause" can be spotted.

    If the sort of pause command can be found - then if it is LMS originated - it can be tracked.

  8. #8
    Senior Member chaug's Avatar
    Join Date
    Jun 2011
    Posts
    103
    Thank you all for your thoughts and suggestions. Turning the auto-power-off feature off made the problem go away. So there must be a bug there. (If anyone wants to reproduce the problem, note that I used the "Always" setting, as mentioned above. Not sure whether the stop and pause settings work fine, but I believe they do, which would mean that the code where the bug is could be narrowed down quute a lot.)

    Good idea to increase the log level for that feature. Will try that when I have time or when someone says: send me those logs and I'll see if I can fix the bug.
    Server: LMS 8.1.1 on an Ubuntu 18.04 virtual machine
    Players: Radio, Touch, Duet (Receiver & Controller), 2 Booms
    Remote control apps: Material Skin (Web UI), but also SqueezePad (iOS), Squeezecontroller (Android)
    Important plugins: Trackstat, Spicefly Sugarcube, Lazy Search Music, Custom Browse, Multi Library

  9. #9
    Senior Member jth's Avatar
    Join Date
    Apr 2005
    Location
    Phoenix, AZ, USA
    Posts
    380
    I'm the author of the PowerSave plugin. I was able to reproduce this on my Squeezebox Radio, so there's a reasonable chance I'll be able to fix it. I haven't made any changes to the plugin for over 10 years (!) so it might take a little while to remember how to package up a new version for distribution.

  10. #10
    Senior Member chaug's Avatar
    Join Date
    Jun 2011
    Posts
    103
    Wow, that is fantastic! I wasn't even aware that Power Save is a plugin. Probably because I installed it about 10 years ago and took it for granted after that. I guess that's a good thing. Excellent work! And over all those years, you probably helped save tons of CO2 emissions.
    Server: LMS 8.1.1 on an Ubuntu 18.04 virtual machine
    Players: Radio, Touch, Duet (Receiver & Controller), 2 Booms
    Remote control apps: Material Skin (Web UI), but also SqueezePad (iOS), Squeezecontroller (Android)
    Important plugins: Trackstat, Spicefly Sugarcube, Lazy Search Music, Custom Browse, Multi Library

Tags for this Thread

Posting Permissions

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