FS#10102 - progress doesnt get updated on the first track of a rockbox session

Attached to Project: Rockbox
Opened by Jonathan Gordon (jdgordon) - Monday, 06 April 2009, 07:20 GMT
Last edited by Boris Gjenero (dreamlayers) - Tuesday, 21 April 2009, 03:57 GMT
Task Type Bugs
Category Music playback
Status Closed
Assigned To No-one
Operating System All players
Severity Low
Priority Normal
Reported Version Version 3.2
Due in Version Undecided
Due Date Undecided
Percent Complete 100%
Votes 0
Private No


seems  FS#9795  caused the first track of a rockbox session to sometimes not update the track position. and it didnt get caught in testing :/

Index: apps/gui/gwps-common.c
--- apps/gui/gwps-common.c (revision 20633)
+++ apps/gui/gwps-common.c (working copy)
-361,6 +361,9 @@
cue_find_current_track(curr_cue, id3->elapsed);
cue_spoof_id3(curr_cue, id3);
+ if (wps_state.id3->elapsed == 0)
+ wps_state.id3 = audio_current_track();

retval = gui_wps_redraw(gwps, 0,
gwps->state->do_full_update ?

^^ that is the simple band aid fix, which I dont like and would rather not commit it...
I've done some debugging and the correct id3 struct is getting passed to the wps, and it is getting updated in playback.c... so im a bit baffled... (also its midnight so im asleep)

crap... added some %p printfing and even though audio_current_track() is returning thistrack_id3 (as it should).. that is apparently pointing to the wrong thing for the first track!
should be a simple fix in the morning... untill then, use the above bandaid if you cant wait that long
This task depends upon

Closed by  Boris Gjenero (dreamlayers)
Tuesday, 21 April 2009, 03:57 GMT
Reason for closing:  Fixed
Additional comments about closing:  Status bar problem fixed in r20705.
FLAC divide by zero problem fixed in r20764.
Comment by Steve Bavin (pondlife) - Monday, 06 April 2009, 08:06 GMT
I've not seen this (with MP3 files)... must be some factor that causes it.
Comment by Thomas Martitz (kugel.) - Monday, 06 April 2009, 10:30 GMT
I've seen it with mp3.
Comment by Jonathan Gordon (jdgordon) - Monday, 06 April 2009, 16:08 GMT
I've only reproduced on the e200 sim, and it was confirmed on e200 target in irc. pondlife, your target is h300 yeah? I think whats happening is that there is an extra call to audio_current_Track() (even if the remote isnt plugged in) which does bassically what this patch does.
Comment by Boris Gjenero (dreamlayers) - Monday, 06 April 2009, 17:30 GMT
I have not seen this. I've used: 5G 30GB iPod, 5G sim, e200 sim, V2 Recorder, V2 Recorder sim. It must only happen under certain circumstances. (I thought I saw this on the V2 Recorder sim, but what I saw was due to the mp3 files being unreadable due to file system permissions.)
Comment by Boris Gjenero (dreamlayers) - Wednesday, 08 April 2009, 03:35 GMT
So far I've only found one way to reproduce this behaviour: Create a readable but unplayable file which is the first file in a directory (eg. echo foo > 00.mp3) and then select it to start playback. The (first playable) file after it plays properly, but there the WPS displays temp_id3. The WPS works on the next track, and it even works if I stop playback and start at the unplayable file again.
Comment by Boris Gjenero (dreamlayers) - Thursday, 09 April 2009, 19:26 GMT
I was finally able to reproduce this in the 5G simulator, with one untagged 27 second 44100 Hz 24 bit FLAC file in the root directory, both with r20636 and r20668. It happens almost every time on the first play after starting up the sim. Subsequent plays in the same sim session do not have the same problem. Gdb shows that track_changed_callback() is not being called when this happens. This must mean that the event happens before wps_state_init() has a chance to call add_event(). The only way the problem can happen is if the event is sent between the audio_current_track() call and add_event() call in wps_state_init().

Surprisingly, moving add_event() to before "wps_state.id3 = audio_current_track();" does not help. I'm finding that track_changed_callback() then happens within audio_current_track() at "wps_state.id3 = audio_current_track();". So, audio_current_track() is called there, it sleeps waiting for data, the event is sent, track_changed_callback() properly sets wps_state.id3 to thistrack_id3, and finally the original audio_current_track() call returns &temp_id3 and wps_state.id3 is set to &temp_id3. The bufread() call which puts data into temp_id3 results in sleep(1) calls until the data is available. Commenting out the "else if (tracks[cur_idx].id3_hid >= 0)" block in audio_current_track() fixes the problem, but that is not a proper solution.

I also have another concern, which is purely theoretical. (I've never observed a problem resulting from it.) When starting playback, PLAYBACK_EVENT_TRACK_CHANGE could be sent before data is available. audio_play_start() posts Q_AUDIO_TRACK_CHANGED, which causes a call of audio_finalise_track_change(), which sends PLAYBACK_EVENT_TRACK_CHANGE. This chain of events does not depend on availability of id3 data, and so the event could be sent before data is available. However, the pointer sent is always thistrack_id3.
Comment by Jonathan Gordon (jdgordon) - Monday, 13 April 2009, 06:17 GMT
here is a maybe better fix (And removes the temp_id3 struct which we sort of decided isnt really needed)...
edit: of course there is no "science" behind this fix other than the above comment.... it just happens to work :)
Comment by Thomas Martitz (kugel.) - Monday, 13 April 2009, 10:39 GMT
What does it other than removing temp_id3 (i.e. is that the actual fix, or do I just not see it)?
Comment by Boris Gjenero (dreamlayers) - Monday, 13 April 2009, 17:35 GMT
The problem is that the events I described earlier cause the WPS to display temp_mp3 instead of thistrack_id3. With playbackfix.diff, the WPS will display thistrack_id3. I found two ways to reproduce this bug in SVN, and with playbackfix.diff I cannot reproduce it.

The only question is whether this breaks anything in audio_current_track(). In particular:
Can we be sure that thistrack_id3 points always points to the right place there?
Can return from playlist_get_track_info() be delayed so that the proper ID3 data is overwritten after it?

Earlier, I found a way to take care of the problem in wps_state_init(), but removing temp_id3 is a better solution, if it works correctly.
Comment by Jonathan Gordon (jdgordon) - Monday, 13 April 2009, 17:45 GMT
(i'm at work now so going by memory....)
IIRC the only dangerous part of audio_current_track() is during the ~2s track transition period. if the code is correct then the 2nd part of the if/else if/etc block gets taken and othertrack_id3 is returned which shuold be correct.

It is possible that this causes wierdness but it shuold be very minimal because that temp_id3 struct was only used as a fallback if the real data wasnt avilable yet, in which case, the finished buffering call will eventaully trigger the event so the WPS rechecks audio_current_track(). There could be a problem (timing issue) with things calling audio_current_track() and getting the fallthrough block (so only the path is there) and then maybe yeilding, and during the yeild thistrack_id3 gets populated properly, but now I write this it doesnt sound like it would cause problems....

Lastly, that theoretical problem, I think it should be documented in a comment in the code somewhere and not worried too much about.. it hasnt shown up and will fix itself up pretty quickly if it ever happens...

if either of you want to commit playbackfix.diff, be my guest... otherwise i'll do it tonight unless it magically gets some testing before then
Comment by Boris Gjenero (dreamlayers) - Wednesday, 15 April 2009, 05:52 GMT
With r20708 and my 5G 30GB iPod, if I start up Rockbox play a FLAC file, go back to the directory browser while the file is playing, and then play an MP3 file, I get
Divide by zero
at 01E80E64 (0)
There isn't a divide call there in the MP3 codec, but there is one in the FLAC codec.

If I remove this patch ( ), the problem goes away. Here's what happens (edited): The id3 info of the currently playing FLAC file is in thistrack_id3. When I play the MP3 file, the changed audio_current_track() overwrites the FLAC id3 in thistrack_id3 with the basic playlist-based id3 of the MP3. The FLAC codec, which is still playing, crashes:
at /home/Boris/rockbox-svn-trunk/apps/codecs/flac.c:494
494 elapsedtime=(samplesdone*10)/(ci->id3->frequency/100);
...because in the basic id3 info, frequency and many other fields are zero.

I am not saying that this patch should be reverted. I like the substantial savings from removing temp_id3. It should be possible to use the not-currently-playing id3 struct.
Comment by Thomas Martitz (kugel.) - Wednesday, 15 April 2009, 07:14 GMT
The id3 shouldn't be changed before the track (and codec in this case) really changed. I'm wondering how this happens. Isn't the id3 supposed to change on the UI track transition, which is even ~2s after the codec track transition Reverting seems bad to me too.
Comment by Steve Bavin (pondlife) - Wednesday, 15 April 2009, 07:25 GMT
To clarify - does the ID3 change when the codec changes or when the track changes? During the transition period, I'd expect audio_current_track() to refer to the track being output (and displayed on the WPS), NOT the track that the (new) codec is processing.
Comment by Boris Gjenero (dreamlayers) - Wednesday, 15 April 2009, 15:24 GMT
If ci.new_track != 0 and automatic_skip == false, how about writing to othertrack_id3 instead of thistrack_id3? It seems that when ci.new_track != 0, the thistrack_id3 <-> othertrack_id3 swap in audio_check_new_track() will happen before the next track starts playing.
Comment by Jonathan Gordon (jdgordon) - Monday, 20 April 2009, 00:44 GMT
where abouts?
Comment by Boris Gjenero (dreamlayers) - Monday, 20 April 2009, 01:32 GMT
I was talking about audio_current_track(). I'm attaching a patch. I am unable to claim that my patch makes audio_current_track() correct. All I can say is that it fixes the divide by zero problem I described and it probably makes the function less broken.

There is only one time when it is ok to write to *thistrack_id3 in audio_current_track(): when the codec isn't active. So !automatic_skip should probably be removed from the if added by write_to_othertrack_id3.patch. Also, the if should maybe test offset instead of ci.new_track. In audio_skip(), direction is first added to wps_offset, and then audio_initiate_track_change() subtracts it from wps_offset and adds it to ci.new_track.
Comment by Boris Gjenero (dreamlayers) - Monday, 20 April 2009, 22:10 GMT
Here is a better, updated patch which addresses the above concerns. It's not perfect, but it solves the problem and works in typical cases.
I think it's only broken when multiple short tracks fit in the PCM buffer. It seems like other things in playback.c are also broken in that case, and I guess that can be another later task.
I also see a theoretical possibility that something else could be using othertrack_id3 as next track or that audio_next_track() could overwrite othertrack_id3. Hopefully this is just a theoretical concern.

I'm pretty sure this can be committed now, and the task can be closed.
Edit: Committed in r20764.