clearly a real and serious issue. bumping severity to critical

I have observed the very same thing with my SB3.  It has happened occasionally, at least since the 6.5.x version of Slimserver.  It has happened at least once since I moved to 7.0 as well.  It has never happened with my SB1 that I can remember.

I first saw this bug back around June-July 2006 timeframe bug didn't correlate it with random mix at the time.

This thread also discusses the behaviour.
http://forums.slimdevices.com/showpost.php?p=244209&postcount=1

My affected system is Windows, and I never power off my SB2/3, but would leave a Random mix paused.
It will unpause itself.

QA to reproduce, capture the following LOGS >plugin.randomplay & >player.source

Anyone else having this issue, please capture the same logs then attach them to this bug, thank you

I will try to get the logs next time this happens.  Only problem is, it happens extremely intermittently -- for me, at least.

Can everybody seeing this provide detailed information about the OS and SC version, please?

I've never seen this myself, using RandomPlay all the time as the alarm clock. My GF would kill me if it started playing a saturday morning...

I have had this happen, but AFAIK not since I got the nightly from about 30 March.  Doesn't mean it's not there though - I don't play random mix all that often :)

I started this thread http://forums.slimdevices.com/showthread.php?t=43422 on the subject.

I would have been using the latest windows 7.0 beta nightly at the time and it was my TP that unpaused itself.

If I find it happens again then I'll try and get some more info.

Michael, I'm running SVN 17808 on Ubuntu 7.04 x86_64

Is anyone seeing this issue using Compact Fluorescent Bulbs?  This maybe a problem with the IR seeing random signals.

There is more to this than just time. An over weekend test did not reproduce the issue with 3 players. 

This has happened a couple of times with my SBR, which would rule out IR, right?

Created attachment 3222 [details]
plugin.randomplay and player.source debug logs during an occurrence

This happened this morning while I had the requested debug logging turned on. I have attached it as server.log.1.

What you can see is:
00:16:41 - I paused the player (with remote) during random song mix.
06:34:02 - A Player::Source::errorOpening was logged
06:34:02 - New play mode: play
06:35:00 - I paused the player again and went back to sleep :)

Specs as below.

SqueezeCenter Version: 7.0.1 - 18355 @ Fri Apr 4 08:08:41 PDT 2008 - Debian - EN - iso-8859-1
Perl Version: 5.8.8 i486-linux-gnu-thread-multi
MySQL Version: 5.0.32-Debian_7etch5
Platform Architecture: i686-linux

Model: Squeezebox v3
Firmware: 86

This is an SB3 on wireless with reasonably bad signal occasionally. I don't think I've ever had the problem on another, wired, SB3.

I had another occurance of this yesterday,

A wired SB1 paused while playing Random Albums was playing when I got home, unfortunately I didn't have logging enabled at the time. One thing that I did notice was that the sun was shining on the player enough that I couldn't read the display. This is with the latest 7.01 windows build and my SBC was not pointing at this player.

Craig

At 6:34 the player is unpausing, Alan any ideas? (from Dean)

I'm wondering what could cause that unpause...  Power loss? Connection loss? 

From my forum thread post at http://forums.slimdevices.com/showthread.php?t=47280:

 - Once the SB3 is in this state, if I hit the power off again on the remote, the same thing happens: it's back to life in under a minute. The only way I have figured out to get it to stay off in this situation is to pause the music before powering off. Then everything behaves normally.

- I'm running Squeezecenter 7.0.1 on a Buffalo Linkstation Pro (with FreeLink Linux).

- I have three SB3s, and I have seen this behavior on two of them, so it's not the specific SB3 unit. (My third SB3 doesn't get used as much as the other two, so perhaps I just haven't used it enough lately to encounter the problem.)

- The times this problem has occurred have all been when playing Random Mix. However, I play Random Mix much of the time, and most of those times this problem does not occur.

- I would estimate the problem happens about one out of five times I turn off an SB3, but it's not consistent. I can't make it happen just by turning an SB3 on and off five or even ten times in a row.

- A significant symptom that the SB3 will turn itself back on is when I power it off, its screen goes completely blank rather than showing the date and time screensaver that's normally displayed when the device is "off" (actually a standby state). If I see a blank screen, I know it's coming back to life on its own.

- One of the times the problem occurred, I had the Squeezecenter window open in my browser, and I could see that even though I had turned off the SB3, Squeezecenter showed that the music was still playing. When the SB3 restarted itself about 30 seconds later, it was playing at the point where Squeezecenter had already advanced. In other words, Squeezecenter never paused or stopped the music during the period when the SB3 was off. On that occasion, I checked the Squeezecenter log immediately afterward, and there did not appear to be any entries or errors related to this happening.

When you get the blank screen, do you get any kind of reboot sequence on the player when it comes back on, or does it just start playing?

(In reply to comment #18)
> When you get the blank screen, do you get any kind of reboot sequence on the
> player when it comes back on, or does it just start playing?

It just starts playing, without any reboot sequence.

Could this be related to the bug where synced players restart if you power off on one?

In that case the screen is also blank and music starts playing.

(In reply to comment #20)
> Could this be related to the bug where synced players restart if you power off
> on one?
> In that case the screen is also blank and music starts playing.

The first couple of times this problem happened to me, my players were synced. However, the problem still occurs occasionally even after I un-synced them.

(In reply to comment #17)

In the synced case, the symptoms you describe are probably related to another problem that I just fixed. But you say that we also get it occasionally when not synced and I think that this must be a different problem.

I think that I may have found a clue here. In the log that was already attached we have the following section:

[08-04-11 00:16:41.8826] Slim::Player::Source::playmode (556) 00:04:20:12:3a:6b: Current playmode: pause
[08-04-11 06:34:02.2121] Slim::Player::Source::errorOpening (1639) Error: While opening current track, so mark it as already played!
[08-04-11 06:34:02.2128] Slim::Player::Source::errorOpening (1639) Backtrace:

   frame 0: Slim::Utils::Log::logBacktrace (/usr/share/perl5/Slim/Player/Source.pm line 1639)
   frame 1: Slim::Player::Source::errorOpening (/usr/share/perl5/Slim/Player/Squeezebox2.pm line 605)
   frame 2: Slim::Player::Squeezebox2::failedDirectStream (/usr/share/perl5/Slim/Networking/Slimproto.pm line 561)
   frame 3: Slim::Networking::Slimproto::_disco_handler (/usr/share/perl5/Slim/Networking/Slimproto.pm line 381)
   frame 4: Slim::Networking::Slimproto::client_readable (/usr/share/perl5/Slim/Networking/Select.pm line 243)
   frame 5: (eval) (/usr/share/perl5/Slim/Networking/Select.pm line 243)
   frame 6: Slim::Networking::Select::select (/usr/sbin/squeezecenter-server line 510)
   frame 7: main::idle (/usr/sbin/squeezecenter-server line 460)
   frame 8: main::main (/usr/sbin/squeezecenter-server line 1017)

[08-04-11 06:34:02.2149] Slim::Player::Source::playmode (298) 00:04:20:12:3a:6b: Switching to mode stop from pause
[08-04-11 06:34:02.2158] Slim::Player::Source::playmode (401) 00:04:20:12:3a:6b New play mode: stop
[08-04-11 06:34:02.2161] Slim::Player::Source::playmode (444) 00:04:20:12:3a:6b: Stopping and clearing out old chunks
[08-04-11 06:34:02.2169] Slim::Player::Source::resetSong (1625) Resetting song buffer.
[08-04-11 06:34:02.2172] Slim::Player::Source::resetSongQueue (1454) Resetting song queue
[08-04-11 06:34:02.2175] Slim::Player::Source::resetSongQueue (1464) Song queue is now 10
[08-04-11 06:34:02.2180] Slim::Player::Source::playmode (556) 00:04:20:12:3a:6b: Current playmode: stop
[08-04-11 06:34:02.2186] Slim::Plugin::RandomPlay::Plugin::commandCallback (1014) Received command playlist cant_open
[08-04-11 06:34:02.2189] Slim::Plugin::RandomPlay::Plugin::commandCallback (1015) While in mode: track, from Main squeeze
[08-04-11 06:34:02.2191] Slim::Plugin::RandomPlay::Plugin::commandCallback (1021) Warning: Last track failed, restarting.

The point is that the randomPlay plugin gets a 'playlist cant_open' and this causes it to restart play. Perhaps the randomPlay plugin should check that the player is on before deciding to restart, although I'm not sure why it should have to expect to handle this case.

But why does it get the 'playlist cant_open'? Because SC gets a DCSO from the player, indicating that the streaming connection has been broken. Why?

Whatever the cause, randomPlay will restart play in circumstances which otherwise would not cause play to restart. If only part of a track has been streamed, the player will be in SC state 'play', in which case play will not restart on DSCO. But if all the track has been streamed, then the state will be 'playout-play', in which case failedDirectStream will skip to the next track. This is inconsistent. The point is that failedDirectStream is not only called for remote streams: it should probably skip-ahead if in mode 'play' or 'playout-play'.

If this theory is correct, then these phantom-restarts can occur occur if using randomPlay (I think) because it no longer know that the player was paused (which would not have caused failedDirectStream to skip-ahead).

But the real question is why do we get the DSCO?

A quick look in the IP3K source shows that the DSCO command is sent on a callback when the TCP socket is closed.  Is it possible that the server or client doesn't explicitly close the connection at the end of the song?  Or, if paused, the socket eventually times out and is closed for some reason.  

In any case, if we are stopped or paused, we should ignore the DSCO message, no?

The strange thing about my experience (and others) of this problem has been that it happen right in the middle of the night.

~3am - 4am GMT which is 7pm to 8pm Pacific. The only time I was actually up at the time the server unpaused itself was close to midnight.

That rules out Microwave interference from my neighbours.

I would have also perhaps suspected something like perhaps a DHCP lease expiring except I use static IP's.

Could there be anything occasiionally happening on SqueezeNetwork around this time that might be affecting servers?

(In reply to comment #25)
> The strange thing about my experience (and others) of this problem has been
> that it happen right in the middle of the night.

This is my experience too, it is almost always midnight to 7am (GMT+12).

> I would have also perhaps suspected something like perhaps a DHCP lease
> expiring except I use static IP's.

I forgot to mention that when I started having this problem back in 6.5.x, I switched to using static IPs.  Doing so *seemed* to reduce the frequency of the problem.

(In reply to comment #24)
> A quick look in the IP3K source shows that the DSCO command is sent on a
> callback when the TCP socket is closed.  Is it possible that the server or
> client doesn't explicitly close the connection at the end of the song?  Or, if
> paused, the socket eventually times out and is closed for some reason.  

The server does close the socket at the end. If we have not got to the end then I cannot see a good reason why the TCP connection would time out.

With modern (wired) ethernet hardware, there is the somewhat annoying tendency of end systems (for example, the player) to treat link-down events (pulling out the cable or rebooting a switch) as fatal to all current TCP connections. Possibly the same applies to wireless links. This seems to go against the philosophy of TCP and connection-less network layers. I have no idea if this could be relevant. Do some routers/bridges/switches/wireless-APs restart themselves regularly?

> In any case, if we are stopped or paused, we should ignore the DSCO message,
> no?

Not exactly ignore, but at least not restart the song or skip to the next. This (desired) behaviour is what SC does: unless playing (actually only playout-play), there is no restart. But the handler in randomPlay overrides this and restarts anyway.

(In reply to comment #0)
> A number of users have reported this on the forums:
> http://forums.slimdevices.com/showthread.php?t=45652
> http://forums.slimdevices.com/showthread.php?t=44779
> http://forums.slimdevices.com/showthread.php?p=269239
> 
> Here's what I've seen:

Please see yet another forum thread about this

http://forums.slimdevices.com/showthread.php?p=308323

I only use SqueezeNetwork, never SqueezeCenter, and can confirm that this behavior of the Receiver turning itself on (or at least the LED coming back on) happens frequently. In fact, I have also experienced times that music starts playing spontaneously. This has happened when I have paused an MP3Tunes playlist, a Pandora station, or a Slacker station, BEFORE turning off the Receiver with the Controller, and then turning off the Controller. I don't think the spontaneous playback has ever occured after I have "cleared" the currently playing selection, rather than just pausing it. Not sure if that helps narrow down the bug.

resetting to unassigned for bug review

need to remove target if we want to get it reviewed

A simple 'fix' would be remove random-play's restart-on-failure functionality. It would be easy to add a test for -is-powered-on but much harder to deal with the paused case (because, in this case, by the time that random-play sees the notification, play will have been stopped).

Andy says that behavior was added to fix bug 4280 and bug 3696 that if there
was a bad track in the playlist the playing would just stop.

It seems like the thing to do is back out those changes and find better fixes
for those bugs.

This should be fixed by reverting the fix for bug 3696 in change 20743.  Please try and reproduce.

Unable to reproduce with 7.1-31761

This bug has now been fixed in the 7.1 release version of SqueezeCenter!  Please download the new version from http://www.slimdevices.com if you haven't already.  

If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.

This bug has been fixed in the 7.3.0 release version of SqueezeCenter!

Please download the new version from http://www.slimdevices.com/su_downloads.html if you haven't already.  

If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.

This happened to me yesterday, not in Random Mix, but for Internet Radio (Slacker or Pandora, can't remember which).  The SB3 turned on in the middle of the night.  No alarms were set (I checked, and we've never used the alarm feature anyway).

Is this likely to be the same bug, or different?

SqueezeCenter 7.2.1 on Mac OS 10.4.11.

(In reply to comment #37)
> This happened to me yesterday, not in Random Mix, but for Internet Radio
> (Slacker or Pandora, can't remember which).  
> 
> SqueezeCenter 7.2.1 on Mac OS 10.4.11.
> 

Different bug, also, please update to 7.3.2 (latest release) and retest.  There were fix's in the SB3 firmware to take care of this issue.

Reduce number of active targets for SC