Bug 4354 - SqueezeBox stops playing unexpectedly
: SqueezeBox stops playing unexpectedly
Status: CLOSED FIXED
Product: SB 2/3
Classification: Unclassified
Component: Audio
: unspecified
: PC Windows XP
: P2 major with 7 votes (vote)
: ---
Assigned To: Chris Owens
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2006-10-12 09:07 UTC by Steve Sheafor
Modified: 2008-12-18 11:41 UTC (History)
7 users (show)

See Also:
Category: ---


Attachments
SqueezeBox stopping - log.txt file #1 (103.15 KB, text/plain)
2006-10-29 10:41 UTC, Steve Sheafor
Details
SqueezeBox stopping - log.txt file #2 (103.23 KB, text/plain)
2006-10-29 10:42 UTC, Steve Sheafor
Details
SqueezeBox stopping - log.txt file #3 (103.37 KB, text/plain)
2006-10-29 10:43 UTC, Steve Sheafor
Details
SqueezeBox stopping - log.txt file #4 (103.25 KB, text/plain)
2006-10-29 10:44 UTC, Steve Sheafor
Details
SqueezeBox stopping - log.txt file #5 (103.37 KB, text/plain)
2006-10-30 07:43 UTC, Steve Sheafor
Details
SqueezeBox stopping - log.txt file #6 (103.03 KB, text/plain)
2006-10-30 07:43 UTC, Steve Sheafor
Details
SqueezeBox stopping - log.txt file #7 (103.37 KB, text/plain)
2006-10-30 07:44 UTC, Steve Sheafor
Details
SqueezeBox stopping - log.txt file #8 (103.17 KB, text/plain)
2006-10-30 07:44 UTC, Steve Sheafor
Details
SqueezeBox stopping - log.txt file #9 (103.28 KB, text/plain)
2006-10-30 16:54 UTC, Steve Sheafor
Details
SqueezeBox stopping - log.txt file #10 (103.06 KB, text/plain)
2006-10-30 16:54 UTC, Steve Sheafor
Details
transition failure slimproto_v extract (389.62 KB, application/zip)
2007-03-09 06:07 UTC, Richard
Details
requested debug flags (25.26 KB, application/x-zip-compressed)
2007-07-02 04:46 UTC, Richard
Details
requested debug flags (more) (29.13 KB, text/plain)
2007-07-02 12:50 UTC, Richard
Details
Log file for comment 58 (41.60 KB, application/octet-stream)
2007-09-09 12:34 UTC, Nigel Birch
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Steve Sheafor 2006-10-12 09:07:57 UTC
I recently downloaded a new version of SlimServer (6.5.1 - 10266), which also loaded a new version 66 of the SqueezeBox firmware (I previously had version 64).  With this new version, roughly one out of every 100 tracks stops playing at the end and does not continue to the next track in the playlist.  The SlimServer display says "PLAY", and the SqueezeBox display says it is playing the selected track with a time of -00:00.  

Selecting PLAY or PAUSE in SlimServer has no effect on playing, although the SlimServer display does change correctly.  Selecting SKIP correctly starts the next song.  Selecting STOP and then PLAY starts the halted song over again at the beginning.

Pressing PLAY on the SqueezeBox remote has no effect, but pressing PAUSE and then PLAY starts the next song correctly.

One time I was able to duplicate this problem by playing the failing song again, but I have had three subsequent failures which were not repeatable.
Comment 1 Steve Sheafor 2006-10-12 13:20:00 UTC
This has happened two more times (out of ~50 songs).  I believe one of my earlier statements was incorrect - pressing PLAY on the SqueezeBox remote restarts the stopped song at the beginning, just like STOP + START does in SlimServer.
Comment 2 Chris Owens 2006-10-13 14:13:00 UTC
Difficult to reproduce, but I'm sure it's annoying.  Have you considered posting to the forums and mentioning the bug number to see if anyone else can add some info to the bug?

Also, to be clear, this is a squeezebox 1?  That is, the sticker on the bottom just says 'Squeezebox' and not Squeezebox2 or Squeezebox v3?

Just a note as well: the SB1 firmware hasn't been changed in a very very long time, so if this is something that only started recently, it's more likely to have its root cause in the Slimserver code rather than the firmware.
Comment 3 Steve Sheafor 2006-10-13 20:41:12 UTC
Subject: RE:  SqueezeBox stops playing unexpectedly

The unit is a SqueezeBox v3 (sorry - I wasn't sure how to distinguish them).
I have only had it for a couple of months.  When I had SlimServer 6.3.1 the
SqueezeBox firmware version (as reported in "Player Settings") was 55.  It
was upgraded to 64 when I first loaded SlimServer 6.5.0, and was upgraded
again to 66 when I did the latest download.  The problem never occurred
prior this upgrade.

-----Original Message-----
From: Slim Devices Bugzilla [mailto:bugs@bugs.slimdevices.com] 
Sent: Friday, October 13, 2006 3:13 PM
To: steve.sheafor@alumni.rice.edu
Subject: [Bug 4354] SqueezeBox stops playing unexpectedly

https://bugs-archive.lyrion.org/show_bug.cgi?id=4354





------- Comment #2 from chris@slimdevices.com  2006-10-13 14:13 -------
Difficult to reproduce, but I'm sure it's annoying.  Have you considered
posting to the forums and mentioning the bug number to see if anyone else
can
add some info to the bug?

Also, to be clear, this is a squeezebox 1?  That is, the sticker on the
bottom
just says 'Squeezebox' and not Squeezebox2 or Squeezebox v3?

Just a note as well: the SB1 firmware hasn't been changed in a very very
long
time, so if this is something that only started recently, it's more likely
to
have its root cause in the Slimserver code rather than the firmware.




------- You are receiving this mail because: -------
You reported the bug, or are watching the reporter.



Comment 4 Steve Sheafor 2006-10-15 15:37:50 UTC
I changed the "Product:" field so it is correct.
Comment 5 Chris Owens 2006-10-16 15:12:23 UTC
Do you notice if it's the same songs each time where it stops?  What kind of tracks are these?  FLAC, MP3, iTunes AAC or lossless?

If you turn on d_slimproto and d_source in the Server settings -> debugging page, does http://localhost:9000/log.txt show anything interesting when the stoppage occurs?  Could you save that .txt file and attach it to the bug?  Thanks!
Comment 6 Steve Sheafor 2006-10-16 16:26:53 UTC
Subject: RE:  SqueezeBox stops playing unexpectedly

Each time it has stopped I have put the same song back into the playlist,
but only once in ~8 tries (all different tracks and different places in
their album) did the same song stop again, so I don't think it is a function
of the particular song.  All tracks which have stopped are MP3s, ripped with
iTunes.

I'll enable the debug flags and let you know if anything shows up.

-----Original Message-----
From: Slim Devices Bugzilla [mailto:bugs@bugs.slimdevices.com] 
Sent: Monday, October 16, 2006 4:12 PM
To: steve.sheafor@alumni.rice.edu
Subject: [Bug 4354] SqueezeBox stops playing unexpectedly

https://bugs-archive.lyrion.org/show_bug.cgi?id=4354





------- Comment #5 from chris@slimdevices.com  2006-10-16 15:12 -------
Do you notice if it's the same songs each time where it stops?  What kind of
tracks are these?  FLAC, MP3, iTunes AAC or lossless?

If you turn on d_slimproto and d_source in the Server settings -> debugging
page, does http://localhost:9000/log.txt show anything interesting when the
stoppage occurs?  Could you save that .txt file and attach it to the bug? 
Thanks!




------- You are receiving this mail because: -------
You reported the bug, or are watching the reporter.



Comment 7 Steve Sheafor 2006-10-16 17:55:16 UTC
Subject: RE:  SqueezeBox stops playing unexpectedly

I enabled the debug flags (also d_slimproto_v and d_source_v).  I then
clicked the "here" in the debug window which brings up the log.txt file.
Each time I do this SlimServer (which is running on a different machine,
which is named Server, from the one I am using) stops!!  I assume this isn't
what is supposed to happen.

If I enable the flags but don't try to look at log.txt, everything works
fine.  However, if I later try to look at log.txt, SlimServer stops.  I also
tried looking at log.txt from the server itself, so I could use
localhost:9000/log.txt, but SlimServer stops then also.

I thought that perhaps it would take some time for log.txt to be
initialized, so I waited for an hour, during which time the SqueezeBox
stopped.  After this, however, an attempt to access log.txt still stopped
SlimServer.  Note that when SlimServer stops I can't look at the log.txt
file from either machine.

I am currently running 6.5.1 - 10337.

-----Original Message-----
From: Slim Devices Bugzilla [mailto:bugs@bugs.slimdevices.com] 
Sent: Monday, October 16, 2006 4:12 PM
To: steve.sheafor@alumni.rice.edu
Subject: [Bug 4354] SqueezeBox stops playing unexpectedly

https://bugs-archive.lyrion.org/show_bug.cgi?id=4354





------- Comment #5 from chris@slimdevices.com  2006-10-16 15:12 -------
Do you notice if it's the same songs each time where it stops?  What kind of
tracks are these?  FLAC, MP3, iTunes AAC or lossless?

If you turn on d_slimproto and d_source in the Server settings -> debugging
page, does http://localhost:9000/log.txt show anything interesting when the
stoppage occurs?  Could you save that .txt file and attach it to the bug? 
Thanks!




------- You are receiving this mail because: -------
You reported the bug, or are watching the reporter.



Comment 8 Chris Owens 2006-10-23 14:52:46 UTC
What version of Slimserver are you running that you see this new debug crashing behavior in?  I'm running SlimServer Version: 6.5.1 - 10449 - Windows XP - EN - cp1252
Comment 9 Steve Sheafor 2006-10-23 17:53:37 UTC
I am running version 10337 - Windows Server 2003 - EN - cp1252.  The operating system is 64-bit Windows XP Pro, so I'm not sure why I have the Server version of SlimServer.  I don't remember if I had this before, but I thought the version typically said "XP".

Is there some way to get the log.txt file without looking at it with Internet Explorer?  That always stops SlimServer.
Comment 10 Chris Owens 2006-10-24 12:32:03 UTC
Okay, sure, you can go to the Windows command line and run 'slim --help' to see the command line options.  You'll probably want to run 'slim --logfile logfilename.txt --d_slimproto --d_source' or something similar.  We can get back to the log file crash later if you want.
Comment 11 KDF 2006-10-24 12:42:05 UTC
fyi - the crash when accessing log.txt was fixed as of 10346, so a newer nightly should allow you access to that again.
Comment 12 Chris Owens 2006-10-25 16:28:33 UTC
I just noticed the crash in bug 4376
Comment 13 Steve Sheafor 2006-10-29 08:17:41 UTC
I downloaded a new version (6.5.1 - 10479), and the log.txt file is now viewable without crashing SlimServer.

I enabled the requested debug flags.  The system has stopped only once, and the behavior is different, as I had to power the SqueezeBox down in order to recover, and also stop and restart SlimServer.  As a result, I was now able to capture the log.txt file.  This version of SlimServer required a new version 67 of the SqueezeBox firmware.
Comment 14 Steve Sheafor 2006-10-29 10:41:53 UTC
Created attachment 1668 [details]
SqueezeBox stopping - log.txt file #1
Comment 15 Steve Sheafor 2006-10-29 10:42:30 UTC
Created attachment 1669 [details]
SqueezeBox stopping - log.txt file #2
Comment 16 Steve Sheafor 2006-10-29 10:43:00 UTC
Created attachment 1670 [details]
SqueezeBox stopping - log.txt file #3
Comment 17 Steve Sheafor 2006-10-29 10:44:27 UTC
Created attachment 1671 [details]
SqueezeBox stopping - log.txt file #4
Comment 18 Steve Sheafor 2006-10-29 10:48:05 UTC
Now that I can look at log.txt without crashing SlimServer, I have captured four versions from two stoppages which have occurred today (the failures seem to be noticeably more frequent than with the earlier version of SlimServer).  The file are:

log_102906A.txt - the log file just after I restarted the playlist (by clicking SKIP) the first time
log_102906B.txt - the log file a short while after that
log_102906C.txt - the log file after the second stoppage, before restarting
log_102906D.txt - the log file just after I restarted the playlist the second time
Comment 19 Steve Sheafor 2006-10-30 07:43:11 UTC
Created attachment 1673 [details]
SqueezeBox stopping - log.txt file #5
Comment 20 Steve Sheafor 2006-10-30 07:43:39 UTC
Created attachment 1674 [details]
SqueezeBox stopping - log.txt file #6
Comment 21 Steve Sheafor 2006-10-30 07:44:01 UTC
Created attachment 1675 [details]
SqueezeBox stopping - log.txt file #7
Comment 22 Steve Sheafor 2006-10-30 07:44:26 UTC
Created attachment 1676 [details]
SqueezeBox stopping - log.txt file #8
Comment 23 Steve Sheafor 2006-10-30 07:46:22 UTC
I have attached four additional log.txt files from stoppages.

log_102906E.txt - the log file after the third stoppage, before restarting
log_102906F.txt - the log file just after I restarted the playlist the third
time
log_102906G.txt - the log file after the fourth stoppage, before restarting
log_102906H.txt - the log file just after I restarted the playlist the fourth
time

This should be plenty of examples - let me know what else I can do to help resolve this.
Comment 24 Chris Owens 2006-10-30 14:57:07 UTC
cc'ing Ross, from our support team, in case he has some ideas.  Since many other users aren't seeing this problem, it seems like it could be an issue he could help with.

There's nothing in those log files that makes me say 'AHA'.  Could I get you to also add d_files and d_firmware?  Just one log should be sufficient.

I apologize for not being able to help more promptly.  I know this must be frustrating for you.
Comment 25 Steve Sheafor 2006-10-30 15:49:33 UTC
I have added the additional debug flags - I'll send log files when this happens again.

Today an even more serious problem occurred.  The SqueezeBox stopped in the middle of a song instead of at the end, and SlimServer was completely hung up.  I could not look at the log.txt files, and SlimServer did not respond to any of the clicks in the SqueezeBox window.  The SqueezeBox itself also would not respond to any commands from the remote.  The Slim icon in the taskbar still said "SlimServer running" when I put the cursor over it.  I was able to right click this and stop SlimServer, but when I tried to restart it I got an error message which said "Unable to start SlimServer.  See Event Log and contact support."  There was nothing in the Event Log other than the stop indication.  I could only recover this situation by rebooting my computer.
Comment 26 Ross Levine 2006-10-30 16:53:30 UTC
Steve have you found any way to reproduce this consistently? 

Also could you think of any strange patterns about when this happens? Is this Squeezebox connected to your network via wireless or a cable? Also whats the make / model number / firmware version of your router? 
Comment 27 Steve Sheafor 2006-10-30 16:54:13 UTC
Created attachment 1678 [details]
SqueezeBox stopping - log.txt file #9
Comment 28 Steve Sheafor 2006-10-30 16:54:37 UTC
Created attachment 1679 [details]
SqueezeBox stopping - log.txt file #10
Comment 29 Steve Sheafor 2006-10-30 16:56:10 UTC
Two more attached log.txt files, including d_files and d_firmware flags.  As before:

log_103006A.txt - the log file after the stoppage, before restarting
log_103006B.txt - the log file just after I restarted the playlist
Comment 30 Steve Sheafor 2006-10-30 17:13:37 UTC
Subject: RE:  SqueezeBox stops playing unexpectedly

Ross,

I have looked carefully for a pattern, but I haven't found one.  The songs
which stop are from random albums, and are random song numbers within the
album.  After several failures I have put the same track back into the
playlist, but only once (out of around 10 tries) did it fail again.

My environment is a Windows 64-bit XP machine where SlimServer runs and the
database is held, another Windows 32-bit XP machine where I typically manage
the database and playlist, and the SqueezeBox, all connected via wired 100
Mbit Ethernet through a C ConnectGear 16-port Ethernet switch.  The switch
also connects to a Linksys Ethernet Cable/DSR Router, Model BEFSR81 V3.  The
router firmware version is 2.50.2.

I think the critical point is that I played > 8,000 tracks without a single
stoppage with SqueezeBox firmware versions 55 and 64, and as soon as I
loaded firmware version 66 (and then later 67) the SqueezeBox stops every
25-50 tracks.

I'll keep looking for patterns.  I just had a failure and sent you the
log.txt files which include the d_files and d_firmware flags.  What else can
I do to help?

-----Original Message-----
From: Slim Devices Bugzilla [mailto:bugs@bugs.slimdevices.com] 
Sent: Monday, October 30, 2006 5:54 PM
To: steve.sheafor@alumni.rice.edu
Subject: [Bug 4354] SqueezeBox stops playing unexpectedly

https://bugs-archive.lyrion.org/show_bug.cgi?id=4354





------- Comment #26 from ross@slimdevices.com  2006-10-30 16:53 -------
Steve have you found any way to reproduce this consistently? 

Also could you think of any strange patterns about when this happens? Is
this
Squeezebox connected to your network via wireless or a cable? Also whats the
make / model number / firmware version of your router? 




------- You are receiving this mail because: -------
You reported the bug, or are watching the reporter.



Comment 31 Chris Owens 2006-11-03 15:21:49 UTC
cc'ing Dan as well
Comment 32 Bradley Phillips 2006-11-05 12:40:03 UTC
I have this same problem. I had assumed it to be a bug in my version. I'm still on a beta 6.5, haven't yet got around to installing the latest official version.

I can discern no pattern to the stoppages, they appear to be random. Almost all of my collection is flac. Sometimes happens every few songs, sometimes plays for hours with no problem.

I plan to upgrade both to Mac OS 10.4 and the latest official SlimServer version shortly. If the problem persists, what do I need to enable help y'all figure out what the issue is.

SlimServer Version: 6.5b1 - 9271 - Mac OS X 10.3.9 (7W98) - EN - utf8
Perl Version: v5.8.1 darwin-thread-multi-2level
MySQL Version: 5.0.22-standard

On a 400MHz G4 Mac with 704MB RAM hardwired to a Squeezebox 3.
Comment 33 Dan Sully 2006-11-06 09:33:15 UTC
Steve - when you've been downgrading the firmware, have you been downgrading the server too?

We'd like to isolate this, and determine if it's a firmware or server issue.

Thanks.
Comment 34 Steve Sheafor 2006-11-06 14:15:08 UTC
Subject: RE:  SqueezeBox stops playing unexpectedly

I have never successfully "downgraded" the firmware.  One time a couple of
months ago I tried to go from SlimServer 6.5.0 back to 6.3.1, but simply
installing the software did not install the "old" (version 55) firmware, and
the old software wouldn't run with the new (version 64) firmware.  After
talking to tech support, it seemed like there was a way to do this, but we
decided I would just keep 6.5.0 and work around bugs I was finding in 6.5.0.

As a result, my statistics on number of failing tracks means that for two
months I had versions 55 and 64 I never saw an error, and then when a new
SlimServer version installed a new version 66 of the firmware the failures
began, and continued when the firmware was upgraded to version 67.  I never
have gone back and tried to recreate the "good" environment.

Strangely enough, I have not had a single stoppage in the last 5 days.  The
versions of both firmware (67) and software (10479) have not changed.  This
"good" period began when I reinstalled Windows and then reinstalled
SlimServer, but I had done that several times during the "bad" period to no
effect.  One thing which is different is that I have added only a few tracks
to the database in the last week, whereas before I was ripping 25-50 CDs
each day, which definitely caused a lot of database thrashing.  Perhaps this
is related to the issue somehow.

-----Original Message-----
From: Slim Devices Bugzilla [mailto:bugs@bugs.slimdevices.com] 
Sent: Monday, November 06, 2006 10:33 AM
To: steve.sheafor@alumni.rice.edu
Subject: [Bug 4354] SqueezeBox stops playing unexpectedly

https://bugs-archive.lyrion.org/show_bug.cgi?id=4354





------- Comment #33 from dan@slimdevices.com  2006-11-06 09:33 -------
Steve - when you've been downgrading the firmware, have you been downgrading
the server too?

We'd like to isolate this, and determine if it's a firmware or server issue.

Thanks.




------- You are receiving this mail because: -------
You reported the bug, or are watching the reporter.



Comment 35 Steve Sheafor 2006-11-14 07:52:02 UTC
After a number of days with no failures, the stopping problem (every ~25-40 tracks) is back.  The only thing which happened was that I removed the machine I use as a client from my network for several days, and then reconnected it.  SlimServer (running on a different machine) was still at exactly the same place in the playlist that it was when I removed the client, but immediately began stopping frequently.  I can't see how the client could affect this behavior - does this ring bells anywhere?
Comment 36 Philip Meyer 2007-03-04 04:37:48 UTC
I have been experiencing exactly the same problem.  I have done lots of investigations to eliminate possible causes, but still have the problem.

I have posted my investigations in the beta forum, under a thread title "Slimserver not always transitioning between tracks".

In summary, I believe it is not due to any third-party plugin.  It is not due to crossfade.  I believe it is not a firewall issue (problem has occured with firewall disabled).

I had the same problem occuring through SoftSqueeze.  Repeatedly so - no track would transition to the next.  This tends to suggest that the problem is not Firmware related?  However, SoftSqueeze now appears to work okay (not sure what I did; could be related to lame.exe, although I was not transcoding, so lame shouldn't be used).

I have tried playing a static playlist of shortish tracks; using random play, and also playing one track with "repeat all" turned on.  All of these modes of playback cause the problem to occur randomly.

At one point I suspected that maybe there were TCP socket connections being opened and not closed properly, as my firewall was listing >30 connections.  However, this issue seemed to be related to the web UI (or my firewall wasn't removing the connections from its display list correctly - Netstat didn't report them).
Comment 37 Richard 2007-03-09 06:07:28 UTC
Created attachment 1836 [details]
transition failure slimproto_v extract

I think bug https://bugs-archive.lyrion.org/show_bug.cgi?id=4232 may be related to this one.

I finally managed to get the transition error under a fairly heavily controlled conditions "--d_source --d_slimproto_v". A section of that log has been attached.

SlimServer Version: 6.5.2 - 11542 - Windows XP - EN - cp1252
Perl Version: 5.8.8 MSWin32-x86-multi-thread
MySQL Version: 5.0.22-community-nt
Player firmware: 76
Audio: stop at power off, remain stopped at power on
Now Playing: small spectrum and remaining time

The base scenario was that I left my laptop over night connected wireless to a known good AP. I had a SQB3 connected wireless to the same AP. At 12:42pm the next day (as recorded by the event log on my laptop), I disconnected the power to the AP (forgetting that I was testing). At around 1:12 (again as reported by the event log) I remembered the test, and replugged the AP. At around 2pm, I noticed that the SQB was displaying Now Playing and the remaining time showed 0 seconds. There was certainly another song in the queue since it said playing 5 of 10.

A summary of the log file reveals that at 12:42, slimserver recognized the SQB as "missing" and went into a check SQB alive state. 30 seconds later, slimserver decided that the SQB was not alive, and no further messages appear. At 13:13 the SQB becomes readable, and the HELO handshake begins. While reading frames from the SQB (after sending 10 frames in succession), an odd looking frame is sent from the SQB to slimserver. The frame contains some null characters. At around the same time, my plugin (a variation of Random Mix run from a timer proc) starts looking for music to play. The SQB then plays music for 4 songs, and at 1:34pm things get interesting. Slimserver reports that the SQB buffer is emptying out during playout-play. 30 seconds later, decoder underrun give us "Decoder underrun while this mode: playout-play," but 1 second later we get: "Decoder underrun while this mode: play". Things head downhill fast from here. And the transition to the next song never *really* happens.. although slimserver and SQB both think it did.

Both the song that the transition fails from and the song that the transition fails to are flac and playable by the SQB. I tested both tracks (-t) using flac 1.1.3, and they report as ok.

Here is the odd frame sent during the HELO handshake - after the 10 successive frames sent from slimserver to the SQB:

2007-03-09 13:13:07.3097 state: DATA, framelen: 43, inbuflen: 0
2007-03-09 13:13:07.3098 attempting to read 43 bytes
2007-03-09 13:13:07.3099 Got 43 bytes from client, 0 remaining
2007-03-09 13:13:07.3103 00:04:20:06:2b:60 Squeezebox stream status:
	event_code:      \x0
\x0
\x0
\x0
\x0a
	bytes_rec_H      0
	bytes_rec_L      42668336
	fullness:        0 (0%)
       bufferSize      3145728
       fullness        0
	bytes_received   42668336
	jiffies:         53900391

Richard
Comment 38 Chris Owens 2007-04-20 13:24:37 UTC
Thanks, Richard!  That looks like good info.
Comment 39 Richard 2007-04-20 14:08:41 UTC
It takes a village..

I added a forced message into source to print decoder underun messages,
and after 2 weeks of playing, my test Squeezebox failed to transition 6
times with a "playout-play" underrun message closely followed by a "play"
underrun message.

I have upgraded v76 to v80 firmware, which in limited tests seems to have
corrected the problem. I'll watch for another 2 weeks for patterns that
indicate that the server has failed to transition properly.
Comment 40 Richard 2007-05-03 05:11:49 UTC
Still having transition trouble with 6.5.2.

One thing that seems unreported is that when the transition fails, the web page enters
an odd state where the player side refreshes every five seconds or so. pressing stop
on the web page, and then pressing play repairs the trouble as pointed out by OP.

Richard
Comment 41 Richard 2007-05-26 12:27:33 UTC
Ok, I realize that this bug has been moved to v7. However, the severity to my business has gone from major to blocker. We run our SQBen in 24x7 establishments, and the recent, persistent troubles with transitions have crippled our business.

I have been running an informal test bed with 3 Fedora Core 5 servers for the past month. I have tried many possible combinations of hardware (swapped NICs, motherboards, memory), OS parameters (apic/apm/acpi/firewall on off), and slimserver configurations (nice -10/+10/browser open/closed perl –w on off webserver forking), but they have all resulted in a failure to maintain a single SQB3 in a state of playing music for longer than 48 hours. And when I open the browser after the failure, the browser is always in an odd state where it is trying to refresh every 5 seconds or so (default skin).

At first, I assumed it was a plugin that was causing the trouble. But after much rewriting/testing, I have discovered a reproducible test case that does not involve any plugins or special configuration. On low end server (2.4GHz Celeron with 256MB RAM) running FC5 with latest updates and fresh install of slimserver 6.5.2. Take any flac library of more than 5,000 tracks. Disable all plugins except network test and Date Time screen saver. Turn on server/plugins/file debugging. Use web browser to open Albums. Select play all albums. Close web browser. Within 24 hours, you will find that the music has failed to transition.

My test case call into question any suggestion that isolating the streaming code (via fork/thread) will solve the problem. In my test case, the server is doing *nothing* but streaming, and it is still failing to transition between tracks properly. I would be happy to forward you a 1U rackmount server that is exhibiting this problem.  

Can someone please, please take resources off of other things and fix this problem. It is seriously a big problem for my business. I would love to just fix it.. but this is clearly a firmware/software disconnect. I have verified that this is a continuing problem up to and including firmware 81 (slimserver 6.5.2 and 6.5.3).

Please HELP!
Comment 42 Chris Owens 2007-05-29 15:51:31 UTC
I'll see what I can do.
Comment 43 Richard 2007-05-30 05:07:25 UTC
Thanks Chris!

I have a 6.3.1/SQB3 combination that has been playing 24/7 since February.

SlimServer Version: 6.3.1 - 8476 - Linux - EN - utf8 

It has not so much as hiccuped (music wise) even once in well over 3 months. And the server has been on for much longer than that. I am just counting the time that has passed since the SQB power button was pressed. The server is using a variation of Random Mix in the newsong event to generate playlists.

What I did notice was that there were periods when duplicate newsong events were being generated in a very small amount of time. This was random in nature (just like our current problem). If you look at the logfile I attached to this bug, you will see that we are getting duplicate underrun messages (one in playout-play and one in play) right before the failure to transition.

Is it possible that the state of the SQB/Source protocol during underrun has been "broken" (generating a second underrun while already processing an underrun) for a while, but that 6.3.1 had some protection that was removed in the 6.5 branch?

Again, thanks for taking the time to look into this. If there is anything that we can provide to help, please don't hesitate to ask. 

Richard
Comment 44 Chris Owens 2007-05-30 09:55:28 UTC
Basically I've created a virtual machine image which hopefully will display the problem, so I can make the failing image available to our developers.  The image has been running since yesterday at 3:45pm, and I have a squeezebox connected with the start time, date, bug number, and a couple other notes on a post-it stuck to its face.

If I have trouble reproducing the issue, I may get back to you to request more info!  It's still playing so far.
Comment 45 Chris Owens 2007-05-31 09:32:22 UTC
I was able to reproduce this even on XP with a playlist of only 60 songs.  Shuffle by song and repeat all were both set.

The display had stopped with a full progress bar and the remaining time at 00:00.  It stopped some time last night, suggesting a run time before the pause of about 36 hours in my case.  I'm going to research it to try to learn some more about the root cause.
Comment 46 Richard 2007-05-31 12:39:37 UTC
If you disable warnings in slimserver.pl, you should be able to decrease the amount of time until the failure.

Welcome to the party.
Comment 47 Andy Grundman 2007-06-01 07:58:48 UTC
These logs would be a bit easier to look through if you didn't use the _v option, would you be able to make one with just --d_directstream --d_source --d_slimproto ?  I'd also ask you to remove all 3rd party or custom plugins, even if you are sure they aren't causing the problem.  And of course, use the latest 6.5.3 nightly build.
Comment 48 Chris Owens 2007-06-01 09:32:09 UTC
My test image crashed last night.  I'll set up to make the logs you suggest over the weekend, Andy.
Comment 49 Richard 2007-06-27 17:11:22 UTC
Are we still waiting for the log files, or do you need me to do this?
Comment 50 Andy Grundman 2007-06-28 10:49:27 UTC
Yeah I still need logs.
Comment 51 Dan Goodinson 2007-06-29 04:39:16 UTC
If it helps at all, I get this problem on virtually every track.  I'm currently running SB1, and had to downgrade version of SlimServer: this problem made it pretty much impossible to enjoy my music.  My player is on firmware version 40.  I play a mixture of MP3s and FLAC - the problem seems to happen on both formats with no apparent pattern.

You know how for the very last part of the track, SB display will change to show the next track?  So - normally - as the track finishes, the display will actually be incorrect for last few seconds?  I think maybe that is when the skip happens - seems to me that rather than play out after the diplay changes, SlimServer instead jumps ahead to next track (possibly)?

I've downgraded my version of SS as it really is just too annoying.  Is it possible to install 2 versions of SS on the same system?  If so, I can do this then get some logs if it helps?

Comment 52 Dan Goodinson 2007-06-29 04:44:54 UTC
I downgraded to 6.3.1, by the way.  The problem doesn't happen at all in this version of SS.
Comment 53 Andy Grundman 2007-06-29 08:18:07 UTC
The SB1 doesn't have a 'track start event' like the SB2/3 so that's why the display updates before the next track actually starts playing.  I tried to fix this once but could not get it to work reliably.
Comment 54 Richard 2007-07-02 04:46:22 UTC
Created attachment 2058 [details]
requested debug flags
Comment 55 Richard 2007-07-02 04:48:26 UTC
Comment on attachment 2058 [details]
requested debug flags

Yeah, I attach the logs with the output you asked for.

It died with a "Track failed before playback" on this track:

[i386-linux]# ./flac -t "/RDA/music/flac/Robert's Library by Genre/
Vocal/Peggy Lee/Peggy Lee -  Hits/Ain't Nobody's Business If I Do.flac"

flac 1.1.1, Copyright (C) 2000,2001,2002,2003,2004 Josh Coalson
flac comes with ABSOLUTELY NO WARRANTY.  This is free software, and you are
welcome to redistribute it under certain conditions.  Type `flac' for details.

Ain't Nobody's Business If I Do.flac: ok
Comment 56 Andy Grundman 2007-07-02 08:39:53 UTC
Were there any tracks after "Ain't Nobody's Business If I Do" that should have played but didn't?  For some reason this track failed to play right after it started streaming.  Does this track usually play OK?
Comment 57 Richard 2007-07-02 12:50:48 UTC
Created attachment 2059 [details]
requested debug flags (more)

Here is the rest of the log when I do the following:

1) press stop in the browser interface
2) press play in the browser interface

"Ain't Nobody's Business" plays correctly and transitions to the next song.
Comment 58 Nigel Birch 2007-09-09 12:33:22 UTC
On v6.5.5 r12598 on WinXP (802.11g WPA2 wireless for SB2, 100Mbps wired for server), I'm seeing the same behaviour.  It started a while ago, but I don't remember when or what changed.  I've got a load of plugins, and I haven't yet tried without them (or on wired, for that matter).

I'll attach a log file next with --d_directstream --d_source and --d_slimproto.  The problem occured at about 15:21 whilst on track 6.  Track 6 had been prevously paused at 14:54 and the PowerSave plugin had powered off the SB2.  I then powered on the SB2 and unpaused track 6 - that's where the log starts.  The problem occured later during track 6.  To fix the problem (SB2 display says playing but no sound and time not changing), I stopped the track (held pause) and then pressed play.
Comment 59 Nigel Birch 2007-09-09 12:34:55 UTC
Created attachment 2131 [details]
Log file for comment 58
Comment 60 Chris Owens 2007-10-15 16:52:12 UTC
I don't see a smoking gun in the log file.

I assume it doesn't always crash on the same file, or else you would have renamed the bug 'flac file crashes sb3'?

I haven't ever been able to reproduce this bug, but clearly it is annoying a fair number of our users.
Comment 61 Richard 2007-10-16 10:33:12 UTC
Hi Chris,

In comment 45, didn't you say you reproduced the behavior running an XP VMware instance?
Comment 41 suggests a way to reproduce the problem in a 24 hour period.

And there may not be a gun, but there is definitely smoke. In all cases where the behavior
appears, there is a duplicate underrun message. The secondary underrun is what causes the
server to fail to transition to the next track since it believes it is playing the next track
when the SQB believes it is still playing the current track. Looking at the log generated by
Nigel and extracting only underrun messages:

2007-09-08 15:17:39.0934 00:04:20:05:ab:ab: Decoder underrun while this mode: playout-play
2007-09-08 15:21:32.8092 00:04:20:05:ab:ab: Decoder underrun while this mode: playout-play
2007-09-08 15:21:32.8645 00:04:20:05:ab:ab: Decoder underrun while this mode: play

The first two messages are ok, but I can't identify the source of the secondary underrun.
Since it is an underrun, it most likely comes from the SQB, or from the socket stack. I
suppose, that if the socket read buffer was too small to get all of the contents, the socket
would still be readable by select the next go around, and slimproto would generate another
underrun message. Or, if the SQB did not 'like' the response it got back from the server,
it might simply resend the underrun message.

I still regularly get the problem on FC5 100Mb 2.4GHz installs, but am seeing less of a problem
running CentOS5 1Gb 3.0GHz installs. But I have not been running the latter long enough to verify
that the OS or NIC type/driver are the problem. I did have a noteworthy case where a server was
playing for 10 days without problem, and within an hour of turning on a computer on the same
switch, the SQB failed to transition.

I think the only way to track this down is to generate the error while you have debug
options/outputs in the firmware\enabled, same for slimserver, and an ethernet tool like ethereal
recording all traffic. I recall a marginally related discussion in a thread where Richard Titmus
found that there were additional arp requests being made by the SQB in a random fashion.

Another case to think about is the changing MAC address case. These days, you'd be hard pressed
to find a true "hub". Most available network concentration devices use switching technology.
Switches tend to map MAC addresses. Unplug a NIC from one port and plug it into another, and
things might not go as expected. If the MAC address of the SQB changed briefly, it would cause
confusion for the switch routing algorithm, and it might just drop MAC unmatched packets. In
some cases when the SQB refuses to connect to a server after an IP address change, simply
unplugging the SQB form the switch, waiting 20 seconds and replugging the SQB into the switch
allows the SQB to connect to the server. 

In any case, my speculation aside, I think that if you build a large library of 5,000 or so
tracks, and select all tracks in the library to play using the browser, you will succeed in
producing the error in less than 48 hours.

Richard
Comment 62 Chris Owens 2007-10-16 15:09:26 UTC
Thank you.  I had forgotten how long it took me to repro the bug.  I will give it another go.
Comment 63 Richard 2007-12-12 08:48:05 UTC
After extensive review of older logfiles, I can see that this problem has been a ghost
in the machine since before 6.2.2 days. My 6.2.2 systems can run for months without
stopping, but they will eventually stop. 6.3.1 systems rarely stop (once a month). And
6.5 series get progressively worse until you get to 6.5.5. 6.5.5 on a VIA 1Ghz cpu will
stop every few hours.

Sorry for the disinformation below concerning 6.3.1 and prior versions as being without
this unexpected behavior. I guess I will check out the 7.0 series since I don't have a
safe haven version.
Comment 64 Chris Owens 2008-01-09 13:12:34 UTC
Hi Steve, now that we have announced the Squeezebox Duet product, I can say we ran into this bug or a very similar one with the new Squeezeboxes during qualification, and fixed it as far as what we were seeing.  Architecturally they are very similar to the SB3 (which we are now supposed to call the Squeezebox Classic), and their firmware is built on the same code base.  So I have my fingers crossed that this work may have fixed the problems you were experiencing.  7.0 is definitely worth a try.
Comment 65 Steve Sheafor 2008-01-09 14:44:58 UTC
Sometime early in 2007, this problem completely went away for me and has never returned.  The improvement did not seem to be related to any SlimServer updates I did.  I have been running 7.0 since late October, and I've never seen this problem with it.
Comment 66 Blackketter Dean 2008-01-21 19:44:32 UTC
Appears to be fixed.  Please reopen if you are still experiencing it with the latest 7.0 software.
Comment 67 James Richardson 2008-05-15 12:58:54 UTC
This bug has recently been fixed in the latest release of SqueezeCenter 7.0.1

Please try that version, if you still see the error, then reopen this bug.

To download this version, please navigate to: http://www.slimdevices.com/su_downloads.html