If item in queue can't be played, StreamingController doesn't recover

[michaelherger]

Here's an issue that was first brought to my attention in https://forums.slimdevices.com/forum/user-forums/deutsch/1694993?p=1727118#post1727118 (I'm sorry, it's German...): the user reported that trying to play some station which failed to load would cause the player to go silent, and he'd have to restart LMS in order to recover.

Investigating something completely different I stumbled across the same issue: a playlist in which the first item isn't available any more (a file I have removed).

[24-11-08 15:43:35.5771] Slim::Formats::readTags (176) File missing: /Users/mherger/Music/Society of Sound/Peter Gabriel/And I'll Scratch Yours - SoS Music 66 - FLAC16/2. Come Talk To Me.flac
[24-11-08 15:43:43.0274] Slim::Player::Protocols::File::open (101) Error: could not open /Users/mherger/Music/Society of Sound/Peter Gabriel/And I'll Scratch Yours - SoS Music 66 - FLAC16/2. Come Talk To Me.flac: No such file or directory
[24-11-08 15:43:43.0277] Slim::Player::Song::open (497) Warning: stream failed to open [tmp:///Users/mherger/Music/Society%20of%20Sound/Peter%20Gabriel/And%20I%27ll%20Scratch%20Yours%20-%20SoS%20Music%2066%20-%20FLAC16/2.%20Come%20Talk%20To%20Me.flac].

In the reporter's case it was an online radio station failing to connect to. The reason doesn't seem to matter.

LMS then jumps to the second track, but gets stuck with a flood of the following messages:

[24-11-08 15:43:43.0341] Slim::Player::StreamingController::_BadState (317) 6e:ea:b1:81:06:5b: event NextTrackReady received while in invalid state BUFFERING-TRACKWAIT
[24-11-08 15:43:43.0389] Slim::Player::StreamingController::_eventAction (287) 6e:ea:b1:81:06:5b:  NextTrackReady with action Slim::Player::StreamingController::_BadState resulted in invalid state BUFFERING-TRACKWAIT
[24-11-08 15:43:43.0391] Slim::Player::StreamingController::_eventAction (287) 6e:ea:b1:81:06:5b:  NextTrackReady with action Slim::Player::StreamingController::_Stream resulted in invalid state BUFFERING-TRACKWAIT
[24-11-08 15:43:43.0393] Slim::Player::StreamingController::_eventAction (287) 6e:ea:b1:81:06:5b:  Play with action Slim::Player::StreamingController::_StopGetNext resulted in invalid state BUFFERING-TRACKWAIT
[24-11-08 15:43:43.0421] Slim::Player::StreamingController::_BadState (317) 6e:ea:b1:81:06:5b: event StatusHeartbeat received while in invalid state BUFFERING-TRACKWAIT
[24-11-08 15:43:43.0424] Slim::Player::StreamingController::_eventAction (287) 6e:ea:b1:81:06:5b:  StatusHeartbeat with action Slim::Player::StreamingController::_BadState resulted in invalid state BUFFERING-TRACKWAIT
[24-11-08 15:43:43.1567] Slim::Player::StreamingController::_BadState (317) 6e:ea:b1:81:06:5b: event StatusHeartbeat received while in invalid state BUFFERING-TRACKWAIT
[24-11-08 15:43:43.1571] Slim::Player::StreamingController::_eventAction (287) 6e:ea:b1:81:06:5b:  StatusHeartbeat with action Slim::Player::StreamingController::_BadState resulted in invalid state BUFFERING-TRACKWAIT
[24-11-08 15:43:43.2994] Slim::Player::StreamingController::_BadState (317) 6e:ea:b1:81:06:5b: event Started received while in invalid state BUFFERING-TRACKWAIT
[24-11-08 15:43:43.2997] Slim::Player::StreamingController::_eventAction (287) 6e:ea:b1:81:06:5b:  Started with action Slim::Player::StreamingController::_BadState resulted in invalid state BUFFERING-TRACKWAIT
[24-11-08 15:43:44.3710] Slim::Player::StreamingController::_BadState (317) 6e:ea:b1:81:06:5b: event StatusHeartbeat received while in invalid state BUFFERING-TRACKWAIT
[24-11-08 15:43:44.3713] Slim::Player::StreamingController::_eventAction (287) 6e:ea:b1:81:06:5b:  StatusHeartbeat with action Slim::Player::StreamingController::_BadState resulted in invalid state BUFFERING-TRACKWAIT
[24-11-08 15:43:45.4517] Slim::Player::StreamingController::_BadState (317) 6e:ea:b1:81:06:5b: event StatusHeartbeat received while in invalid state BUFFERING-TRACKWAIT
[24-11-08 15:43:45.4522] Slim::Player::StreamingController::_eventAction (287) 6e:ea:b1:81:06:5b:  StatusHeartbeat with action Slim::Player::StreamingController::_BadState resulted in invalid state BUFFERING-TRACKWAIT

@philippe44 - I was able to narrow this down to PR #985: Commit 25f72e4 (one before merging your PR) would work. Commit 4bc6029 (the PR merge) would fail. That PR indeed modified the StreamingController. Could you please try to reproduce this issue?

[chetmurthy]

I have had this problem for several years with earlier versions of LogitechMediaServer: I found that after version 8.2.0 (IIRC) all newer versions had this bug. In my case, there's nothing in the logs to indicate that something went wrong. Typically the player encounters an unplayable file, it moves to the next file, starts playing that, but then it hangs. I need to kill/restart the player server in order to recover.

If there were some way for me to turn on debug logging, I could do so and submit traces of the failure scenario.