Pandora says there's no good way to reproduce this with their content, maybe reproduce it with local music.  At least check the calculations.

This is not reproducible with local music.

Andy could you cast your eye over the code and see if there's any obvious reason for this bug?

If not, I will push back that we can't repro it so it must not be that important.

My hunch is that the track length metadata returned by Pandora was wrong for this one track, causing the incorrect progress bar.  But I don't have any way to check this, maybe you can Vic?  If you think it's a general problem with long tracks, maybe you could create a test station that only plays this one track over and over, or only tracks > X minutes or something like that.

OK I forgot we are still manually calculating length from the Content-Length header (you should bug your devs to add duration metadata so we can stop making wasted requests to your servers!).  So I'm not sure why this would have happened.  We'd need a way to reproduce.

I was able to reproduce this... by listening to a ton of music this afternoon and checking the status indicator all the time.  It happened on a 7:21 track.  But it seems difficult to repro.

We'll have to talk to Pandora some more about this one, I guess.

I think this is a general-purpose SP bug, I have seen progress bar problems on non-Pandora tracks.  Assigning to Ben.

FYI, this is going to be very difficult to fix without a clear means of reproducing the issue. I have tried with several files, both Pandora and local, and not been successful.

in NowPlayingApplet.lua, this is the line that determines what gets displayed

strRemain = "-" .. _secondsToString(duration - elapsed)

so, if strRemain is displayed as "-59:00", then duration - elapsed would have to be erroneously in the range of 3540 seconds.

Alternatively, maybe there's a bug in _secondsToString()

I don't see a smoking gun there either though...

local function _secondsToString(seconds)
        local hrs = math.floor(seconds / 3600)
        local min = math.floor((seconds / 60) - (hrs*60))
        local sec = math.floor( seconds - (hrs*3600) - (min*60) )

        if hrs > 0 then
                return string.format("%d:%02d:%02d", hrs, min, sec)
        else
                return string.format("%d:%02d", min, sec)
        end
end


My money's on bad data from the server causing the problem.

Sorry Chris, back to QA. I don't see anything obvious on the SP side. I don't know what I can do with this without a means of reproducing.

Andy, if you're reading this-- is it possible that the server is putting quotes around duration or elapsed and sending it as a string instead of a number? I'm kind of doubting this could be a data type issue because I think the failure would have been different, but thought I'd ask...

I didn't get any good debug information, but I just reproduced this.

SB Touch was displaying remaining time as 57+ minutes and was counting down each second. I quickly launched desktop squeezeplay and pointed it to the SB Touch and on the desktop squeezeplay, the remaining time was correct.

When the track changed, both Touch and Desktop SP updated their NP screens and neither had a problem with the remaining time.

I'm now feeling this is more likely SP-side only.

seeing this frequently enough on Last.FM that I think I'll be able to reproduce and capture some debug when I do. Assigning back to myself.

Reproduced this for a track and showed these values for duration and elapsed (in seconds):

20100204 01:29:40.078 WARN   applet.NowPlaying - NowPlayingApplet.lua:661 duration: 234.2740625
20100204 01:29:40.078 WARN   applet.NowPlaying - NowPlayingApplet.lua:662 elapsed: 286.171

elapsed has exceeded duration-- it appears the duration data retrieved for the track is incorrect. Track clearly had more than 234 seconds in its duration and continued to play for several more minutes.

will debug further tomorrow to see if something is amiss in the getTrackElapsed() method that NowPlaying is using to get elapsed and duration data. If not, suspicion goes back to the track metadata, specifically on the duration value

Seen during CAT PR-0091

Also CAT PR2 0097

Also CAT PR2-0108

I captured some quality debug for when the issue was reproduced.

In the 23:01:31 messages everything is in a good state. The following second at 23:01:32, things go haywire.

23:01:31.218 WARN   squeezebox.player - Player.lua:703 trackElapsed: 313.084 self.trackDuration: 313.965625
23:01:31.218 WARN   squeezebox.player - Player.lua:711        self.trackTime: 0.022
23:01:31.218 WARN   squeezebox.player - Player.lua:712    self.trackDuration: 313.965625
23:01:31.218 WARN   squeezebox.player - Player.lua:713  self.trackCorrection: 313.062
23:01:31.218 WARN   squeezebox.player - Player.lua:714  self.trackCorrection was computed by multipling self.rate * ( now - self.trackSeen)
23:01:31.218 WARN   squeezebox.player - Player.lua:715        self.trackSeen: 3775.094
23:01:31.218 WARN   squeezebox.player - Player.lua:716             self.rate: 1
23:01:31.218 WARN   squeezebox.player - Player.lua:717                   now: 4088.156
23:01:32.031 WARN   squeezebox.player - Player.lua:408 updatePlayerInfo: setting player modelsqueezeplay
23:01:32.040 WARN   squeezebox.player - Player.lua:703 trackElapsed: 245.84725 self.trackDuration: 245.83825
23:01:32.040 WARN   squeezebox.player - Player.lua:709 !!!!!!!!!!!!!!!!!!!!!!! Elapsed exceeds track duration !!!!!!!!!!!!!!!!!!!!!!!!!!!
23:01:32.040 WARN   squeezebox.player - Player.lua:711        self.trackTime: 245.83825
23:01:32.040 WARN   squeezebox.player - Player.lua:712    self.trackDuration: 245.83825
23:01:32.040 WARN   squeezebox.player - Player.lua:713  self.trackCorrection: 0.0090000000000146
23:01:32.040 WARN   squeezebox.player - Player.lua:714  self.trackCorrection was computed by multipling self.rate * ( now - self.trackSeen)
23:01:32.040 WARN   squeezebox.player - Player.lua:715        self.trackSeen: 4088.97
23:01:32.040 WARN   squeezebox.player - Player.lua:716             self.rate: 1
23:01:32.040 WARN   squeezebox.player - Player.lua:717                   now: 4088.979
23:01:32.040 WARN   squeezebox.player - Player.lua:703 trackElapsed: 245.84825 self.trackDuration: 245.83825


some observations:
There is a playerstatus update to begin the messages at 23:01:32.

self.trackTime appears to be the bad seed here. self.trackCorrection and self.trackDuration are likely correct to the track.

attempt at a cleaner paste of debug data from previous comment

23:01:31.218 trackElapsed: 313.084 self.trackDuration: 313.965625
23:01:31.218    self.trackTime: 0.022
23:01:31.218    self.trackDuration: 313.965625
23:01:31.218    self.trackCorrection: 313.062
23:01:31.218    self.trackCorrection was computed by multipling self.rate * ( now - self.trackSeen)
23:01:31.218    self.trackSeen: 3775.094
23:01:31.218    self.rate: 1
23:01:31.218    now: 4088.156
23:01:32.031    updatePlayerInfo: setting player modelsqueezeplay
23:01:32.040 trackElapsed: 245.84725 self.trackDuration: 245.83825
23:01:32.040 !!!!!!!!!!!!!!!!!!!!!!! Elapsed exceeds track duration !!!!!!!!!!!!!!!!!!!!!!!!!!!
23:01:32.040    self.trackTime: 245.83825
23:01:32.040    self.trackDuration: 245.83825
23:01:32.040    self.trackCorrection: 0.0090000000000146
23:01:32.040    self.trackCorrection was computed by multipling self.rate * ( now - self.trackSeen)
23:01:32.040    self.trackSeen: 4088.97
23:01:32.040    self.rate: 1
23:01:32.040    now: 4088.979
23:01:32.040 trackElapsed: 245.84825 self.trackDuration: 245.83825

Here it is in a nutshell. When new track data comes into Player.lua via Playerstatus, sometimes event.data.time is incorrectly set to the same as event.data.duration. event.data.time should be a number very close to 0.

Good data for track A:
00:56:23.900 WARN   squeezebox.player - Player.lua:1215 Playerstatus update, event.data.time: 0.014| event.data.duration: 256
00:56:23.900 WARN   squeezebox.player - Player.lua:1218 Playerstatus update,  self.trackTime: 0.014|  self.trackDuration: 256

Track A ends, Track B starts, Playerstatus update:
01:00:40.307 DEBUG  applet.NowPlaying - NowPlayingApplet.lua:209 Notification received that track has changed

Bad data for event.data.time:
01:00:40.307 WARN   squeezebox.player - Player.lua:1215 Playerstatus update, event.data.time: 238| event.data.duration: 238
01:00:40.307 WARN   squeezebox.player - Player.lua:1218 Playerstatus update,  self.trackTime: 238|  self.trackDuration: 238

I believe I've definitively proved that this is a server-side issue.

On the server, time and duration are added to the playerstatus message with these code snippets

          $request->addResult('time',
                        Slim::Player::Source::songTime($client));

                if (my $dur = $song->duration()) {
                        $dur += 0;
                        $request->addResult('duration', $dur);


So....something occasionally faulty with Slim::Player::Source::songTime($client); ??

unassigning and tagging for bug_meeting. 

A server-side fix is probably in order, but would like to discuss if there is some defensive code I should put on the client side, e.g., setting event.data.time to 0 if event.data.time == event.data.duration

Created attachment 6519 [details]
add defensive code to fix self.trackTime at track boundary when server data is bad

Not checking this in so it doesn't mask verifying a server-side fix. This can be checked in after that...

This appears to be a slimproto race condition.  The elapsed time is updated on 
every STAT packet, which is on a 1-second timer. If a new track starts and STMd 
is sent before the first STAT packet from the new track, the newsong 
notification will send a playerstatus packet with incorrect elapsed time (from 
the previous track). We need to fix this so that the slimproto code always 
sends a STAT packet before STMd on a new track.

Andy, do you mean STMd, or STMa (or is it STMs)? But anyway, the STMa/s, which indicates track start, should have the correct elapsed time for the new track. If it does not then that is the real problem. A fix might just be to force it to report the elapsed time as 0 if it is more than 1 second or so.

My mistake, it is STMs.  So, the elapsed seconds value in that packet must be wrong some of the time, I'll debug it some more.

 == Auto-comment from SVN commit #30155 to the  repo by agrundman ==
 == https://svn.slimdevices.com/?view=revision&revision=30155 ==

Bug 15344, workaround to reset songElapsedSeconds during STMs if value is too high

I checked in a workaround in SBS that resets the songElapsedSeconds value to 0 in STMs if the value is > 5.

I didn't find the real bug in SP.  I noticed that in decode_check_start_point() it always resets elapsed_samples when it notices a new track has started:

	decode_audio->num_tracks_started++;
	decode_audio->elapsed_samples = BYTES_TO_SAMPLES(track_start_offset);

Since STMs is only sent after num_tracks_started is incremented, I don't know how elapsed_samples could have an old value here.  There must be a thread race condition in here somewhere.  Or perhaps some issue with the fifo wrapping around. Alan, maybe you can take a look?

Created attachment 6520 [details]
Short log with a bad STMs

 == Auto-comment from SVN commit #8532 to the  repo by agrundman ==
 == https://svn.slimdevices.com/?view=revision&revision=8532 ==

Fixed Bug 15344, patch from Alan to reset sync_elapsed_samples correctly when changing tracks

 == Auto-comment from SVN commit #30260 to the slim repo by ayoung ==
 == https://svn.slimdevices.com/slim?view=revision&revision=30260 ==

bug 15344: STMs (track started) can be sent with old elapsed seconds data 
Remove workaround from server now that player has been fixed.

This bug has been marked fixed in a released version of Squeezebox Server or the accompanying firmware or mysqueezebox.com release.

If you are still seeing this issue, please let us know!