--- Log for 29.11.122 Server: lithium.libera.chat Channel: #rockbox --- Nick: rb-logbot Version: Dancer V4.16 Started: 3 days and 14 hours ago 01.48.40 *** No seen item changed, no save performed. 01.59.45 # <_bilgus> ok I think I have a pretty good fix now g#4856 01.59.55 # 3Gerrit review #4856 at https://gerrit.rockbox.org/r/c/rockbox/+/4856 : 3RFC playlist_create fix race condition WIP by William Wilgus 02.10.59 # <_bilgus> if you want to repro I have it down to a stience now on start go to playlist catalog start a song then back out of wps and go to bookmarks and choose one, 3/10 you'll get a playlist buffer full, and error accessing playlist message for the rest of the session, 1/10 you'll get a 'Nothing to resume' and 3/10 it'll be the wrong song resumed 02.11.55 # <_bilgus> note you don't actually need any of the bookmark stuff you just need one created 02.13.55 # <_bilgus> I can get the bug on a playlist resume too but its not near as fast 02.17.27 Join fourHZ [0] (~fourHZ@92-52-40-121.dynamic.orange.sk) 02.22.28 # <_bilgus> this applies to devices with dircache 03.22.42 Join mink [0] (~mink@2a07:3e00:81:0:7b6:4663:f93b:9fae) 03.48.43 *** No seen item changed, no save performed. 05.23.21 Join chris_s [0] (~chris_s@ip-095-223-073-220.um35.pools.vodafone-ip.de) 05.37.41 # _bilgus: The issue doesn't seem to turn up when background playlist background scanning (https://github.com/Rockbox/rockbox/blob/0c7394e39a8c2767ea1329ed8ed222805468ec72/apps/playlist.c#L1312)  is deactivated. 05.37.47 # On the official build, the index saved for a bookmark appears to be almost always wrong (in addition to what you've described, now that I've tried it. Haven't checked out g4856 yet... 05.39.38 Quit chris_s (Quit: Connection closed) 05.45.13 Join chris_s [0] (~chris_s@ip-095-223-073-220.um35.pools.vodafone-ip.de) 05.45.49 # (and when dircache_search has been disabled, I guess) 05.45.52 Quit chris_s (Client Quit) 05.48.47 *** Saving seen data "./dancer.seen" 06.25.49 Quit CH23_M (Ping timeout: 260 seconds) 06.29.07 Join CH23_M [0] (~CH23@revspace/participant/ch23) 07.00.24 Quit CH23_M (Read error: Connection reset by peer) 07.02.08 Join CH23_M [0] (~CH23@revspace/participant/ch23) 07.48.48 *** Saving seen data "./dancer.seen" 08.09.43 Join chris_s [0] (~chris_s@ip-095-223-073-220.um35.pools.vodafone-ip.de) 08.12.10 # _bilgus: Actually, strike that. It's actually the "Maintain a list of recent bookmarks" setting that makes the bookmark index go off the rails when saving, if set to "Yes". Is that what you were seeing, too, or yet another bug? I've never had that setting enabled. 08.13.02 Quit chris_s (Client Quit) 08.25.18 Join chris_s [0] (~chris_s@ip-095-223-073-220.um35.pools.vodafone-ip.de) 08.27.13 # That may have been introduced with 88ecaf2. It seems to work in the build before that 08.28.25 Quit chris_s (Client Quit) 08.46.31 # <_bilgus> the issue exists back to 3.15 08.47.43 Join chris_s [0] (~chris_s@ip-095-223-073-220.um35.pools.vodafone-ip.de) 08.49.00 # Are you sure it's the same issue? So far, I can reliably reproduce it in the current build but haven't been able to 221125-853d70. The index appears correctly in the list of recent bookmarks but is wrong in the "List Bookmarks" screen on the WPS 08.51.40 # <_bilgus> No i'm not totally sure but i'll try some more testing 08.52.29 # <_bilgus> the issue I observed happens even when resuming the playlist if you do it fast enough or enough times 08.54.06 Join massiveH [0] (~massiveH@2600:4040:a993:4900:d472:d27c:9382:eecd) 08.54.54 # yeah, I think it's probably two separate bugs. :D 08.56.23 # although, like I said, I haven't tried your Gerrit patch, so who knows... 08.58.51 # <_bilgus> I did some tests last night keeping a copy of the playlist and then checking versus the real playlist and I didn't see any difference between each so its enough to suspend the dircache with the latest patch 09.00.03 # <_bilgus> but I sis still get the wrong track resumed on occasion like 1/50 so its likely there is still a bug 09.00.24 # <_bilgus> did* 09.02.37 # <_bilgus> oddly the bookmark is proper in those cases it just acts like the randomize playlist fn didn't get the indices right 09.03.39 # <_bilgus> but i'll continue to test this eve 09.04.13 # With the thing I was running into when trying to reproduce what you had described, the index is wrong 99% of the time – maybe actually only correct the first time. Then it just seems to stop updating the index altogether (except on the Recent Bookmarks screen) 09.05.32 # <_bilgus> ah I did observe that prior indices shifting but that happened in 3.15 too so not sure 09.07.39 # <_bilgus> after the patch the indice is right and the seed is right its just the track aren't in the right place and choosing the same bookmark again it gets it right 09.07.52 # The workaround is to just disable "Maintain list of recent bookmarks". It works fine at that point... except for what you've described. :D 09.08.07 # <_bilgus> I think its more a timing issue 09.09.23 # <_bilgus> maybe try applying the same bookmark with QS and it'll reappear 09.09.41 # ? 09.10.25 # <_bilgus> when you disable matain a recent list it removes the menu option and it takes a bit longer to go apply a bookmark 09.10.26 # QS 09.10.31 # <_bilgus> quick screen 09.10.59 # <_bilgus> or shortcut screen 09.12.28 # same thing... 09.12.35 # same result, I mean 09.12.46 # using the QS to change the setting 09.13.33 # <_bilgus> oh I figured you could apply the bookmark using it 09.13.49 # <_bilgus> not just change the setting 09.17.17 # I can try, but it seems like the index already gets saved incorrectly in the bookmarks file? 09.17.38 # although the file name is correct 09.20.38 # It's incorrectly saved to the playlist .bmark file, but correctly saved to the os-recent.bmark file) 09.21.15 # <_bilgus> when I just tried it it shows the right indice but still gets it wrong ill try prior builds tonight (this is with 4865 applied) 09.21.50 # <_bilgus> yeah so probably a separate bug 09.22.20 # I guess. I'll try 4865 later tonight and report back if I notice anything different 09.24.04 # <_bilgus> no I get the same if I use the plylist.bmark its wrong where as the recent bmark is right oddly 09.25.07 # <_bilgus> so its might be getting fed the wrong data since with the bookmark patch it has to make two calls to save the two bmarks 09.26.17 # <_bilgus> what I can try is kust make the playlist one and copy it to the recent.nmark instead 09.26.21 # <_bilgus> just* 09.30.07 # yeah, that seems like the issue, for whatever reason 09.48.51 *** Saving seen data "./dancer.seen" 10.34.46 Quit tertu (Ping timeout: 265 seconds) 10.36.08 Join tertu [0] (~tertu@user/tertu) 10.39.48 Quit massiveH (Quit: Leaving) 11.27.28 Quit mink (Remote host closed the connection) 11.32.43 Quit chris_s (Quit: Connection closed) 11.48.53 *** Saving seen data "./dancer.seen" 11.55.26 # <_bilgus> looking at the code I store everything prior to the calls except we keep a pointer to the track id3 for offset and elapsed and make a call to playlist_get_name 11.56.20 # <_bilgus> none of those should have an effect on the indice 12.26.40 Quit jacobk (Ping timeout: 252 seconds) 12.47.13 Join jacobk [0] (~quassel@utdpat242030.utdallas.edu) 13.06.48 Join chris_s [0] (~chris_s@ip-095-223-073-220.um35.pools.vodafone-ip.de) 13.07.47 # looks like parse_bookmark in add_bookmark changes the index 13.13.40 Join mink [0] (~mink@125.215.164.109.static.wline.lns.sme.cust.swisscom.ch) 13.20.05 Quit advcomp2019 (Ping timeout: 260 seconds) 13.20.44 Quit chris_s (Quit: Connection closed) 13.46.44 Quit jacobk (Ping timeout: 256 seconds) 13.48.54 *** Saving seen data "./dancer.seen" 13.57.16 Join chris_s [0] (~chris_s@ip-095-223-073-220.um35.pools.vodafone-ip.de) 13.59.28 # so, apart from the offset and elapsed, apparently the info from the initial bookmark simply gets saved repeatedly as it is last parsed :p 14.02.44 Join jacobk [0] (~quassel@64.189.201.150) 14.03.11 # ... or something like that 14.09.14 # (initial bookmark from the list of most recent bookmarks) 14.17.25 Quit chris_s (Quit: Connection closed) 14.53.21 Quit CH23_M (Ping timeout: 265 seconds) 14.56.48 Quit mink (Remote host closed the connection) 15.23.22 Join advcomp2019 [0] (~advcomp20@user/advcomp2019) 15.46.54 Quit reductum (Quit: WeeChat 2.8) 15.47.28 Join reductum [0] (~reductum@2603-8000-b400-8764-dea6-32ff-fe16-a622.res6.spectrum.com) 15.48.57 *** Saving seen data "./dancer.seen" 16.05.49 Join mink [0] (~mink@213.55.220.132) 16.16.01 Quit jacobk (Ping timeout: 252 seconds) 16.26.59 Quit mink (Remote host closed the connection) 16.27.28 Join jacobk [0] (~quassel@129.110.242.224) 16.52.52 Quit jacobk (Ping timeout: 252 seconds) 16.57.58 Join paulk [0] (~paulk@leonov.paulk.fr) 17.01.06 Quit reductum (Quit: WeeChat 2.8) 17.01.32 Join jacobk [0] (~quassel@utdpat241106.utdallas.edu) 17.01.33 Join reductum [0] (~reductum@2603-8000-b400-8764-dea6-32ff-fe16-a622.res6.spectrum.com) 17.12.16 Quit reductum (Quit: WeeChat 2.8) 17.14.32 Join reductum [0] (~reductum@2603-8000-b400-8764-dea6-32ff-fe16-a622.res6.spectrum.com) 17.48.58 *** Saving seen data "./dancer.seen" 17.52.26 Quit tomato (Quit: The Lounge - https://thelounge.chat) 17.53.04 Join tomato [0] (~tomato@user/tomato) 18.44.28 # <_bilgus> Chris_s (logs) so are you saying its propagating the error then? 19.04.32 Quit fourHZ (Quit: Client closed) 19.08.15 # <_bilgus> no it calls playlist_get_resume_info() 19.10.46 Join chris_s [0] (~chris_s@ip-095-223-073-220.um35.pools.vodafone-ip.de) 19.10.54 # My understanding is, since parse_bookmark overwrites resume_info struct members, and parse_bookmark is used by add_bookmark to load all of the existing bookmarks from the file, the bookmark needs to have already been created beforehand, unless you make sure that the resume_info is (re-)fetched before calling create_bookmark a second time. 19.11.25 # <_bilgus> oh duh 19.13.25 # <_bilgus> I assumed it just grabbed them as entries but makes sense it would parse them to update the last 19.15.40 # wasn't really obvious to me, either, at first... 19.16.57 # <_bilgus> glad you looked at it I'd have spent another few hours before figuring it out 19.18.46 # :) 19.21.39 # <_bilgus> they probably did that because they wanted to support the old format and new format 19.22.28 # ah ok, didn't even know there were different formats 19.23.54 Quit jacobk (Ping timeout: 256 seconds) 19.24.17 # <_bilgus> judging by the new_format check (they start with >) 19.24.30 # right 19.24.47 # <_bilgus> assume old ones didn't and just had the index integer 19.30.57 Join CH23_M [0] (~CH23@revspace/participant/ch23) 19.49.02 *** Saving seen data "./dancer.seen" 21.46.35 Quit chris_s (Quit: Connection closed) 21.49.03 *** Saving seen data "./dancer.seen" 22.00.32 Quit tomato (Quit: The Lounge - https://thelounge.chat) 22.01.08 Join tomato [0] (~tomato@user/tomato) 23.03.09 Quit buZz (Remote host closed the connection) 23.16.49 Join jacobk [0] (~quassel@64.189.201.150) 23.37.11 Quit m01 (Quit: Konversation terminated.) 23.39.23 Join m01 [0] (~quassel@vps-b172b88b.vps.ovh.net) 23.49.04 *** Saving seen data "./dancer.seen"