Bug 16669 - Stops playing WiMP unexpectedly
: Stops playing WiMP unexpectedly
Status: NEW
Product: SB Radio
Classification: Unclassified
Component: Connectivity (Wired)
: Include FW version in comment
: PC Windows XP
: -- normal with 1 vote (vote)
: ---
Assigned To: Unassigned bug - please assign me!
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2010-11-17 16:18 UTC by Mickey Gee
Modified: 2011-04-14 23:34 UTC (History)
3 users (show)

See Also:
Category: ---


Attachments
Log from Radio (176.24 KB, text/plain)
2010-11-17 16:18 UTC, Mickey Gee
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Mickey Gee 2010-11-17 16:18:04 UTC
Using firmware r9219 on wired Radio playing same album from WiMP repeatedly. Player connected only to MySB.com

Bottom left icon went to Stop icon after playing for about 8.5 hours. Diagnostic screen says it's still connected to MySB.com. Logging into MySB.com says it's connected OK, too.

Logs included. Error appears at Nov 17 15:43.
Comment 1 Mickey Gee 2010-11-17 16:18:41 UTC
Created attachment 7040 [details]
Log from Radio
Comment 2 Mickey Gee 2010-11-17 16:20:13 UTC
Pressing Play button resumes play properly.
Comment 3 Mickey Gee 2010-11-17 16:22:17 UTC
Also, can ping, log on to Radio, and scp log without rebooting unit first, so state of network connection is good when problem occurs.
Comment 4 Alan Young 2010-11-17 22:12:18 UTC
(In reply to comment #0)
> Bottom left icon went to Stop icon after playing for about 8.5 hours.
> Diagnostic screen says it's still connected to MySB.com. Logging into MySB.com
> says it's connected OK, too.
> 
> Logs included. Error appears at Nov 17 15:43.

I see what it says in the log. At what time did you observe that it stopped playing?
Comment 5 Alan Young 2010-11-17 22:47:01 UTC
Analysis:

The connection was recognised as having been lost at 15:43:01:

Nov 17 15:43:01 squeezeplay: INFO   net.slimproto - SlimProto.lua:756 connection error: closed, reconnecting in 3.14 seconds
Nov 17 15:43:04 squeezeplay: INFO   net.slimproto - SlimProto.lua:579 connect to baby.squeezenetwork.com (184.73.179.154)
Nov 17 15:43:04 squeezeplay: INFO   net.slimproto - SlimProto.lua:137 Send HELO: reconnect-bit=0 bytesReceived(H,L)=0,7113664

Note that the reconnect bit is not set, implying that streaming the previous track had completed. This is reasonable given that this was 03m40s since the track started streaming.

The following Comet reconnect got the 'invalid client' error.

The subsequent successful reconnect resulted in 'stop' state.

Nov 17 15:43:33 squeezeplay: WARN   applet.AlarmSnooze - AlarmSnoozeApplet.lua:307 notify_playerModeChange: player (LocalPlayer {Squeezebox Radio}) mode has been changed to stop.

For some reason SN did not continue play on reconnect.
Comment 6 Alan Young 2010-11-24 02:14:32 UTC
Mickey, so far I have been unable to come up with a theory as to why music might stop in this case.  It is the case the the stop occurs after a reconnect, presumably after a server-side restart of some kind. It also seems to be the case that the reconnect involves both slimproto and comet connections and I did not think that that would be the case under normal server-process restart scenarios. Andy, can you comment?

It might be possible to get some hints if you can set net.slimproto=DEBUG but the problem is that this will produce rather verbose logging with one message per second while playing and one per 30s when stopped, so you would need to recognize that the problem had occurred soon after the actual event in order to get the logfile before it recycles.