Bugzilla – Bug 4116
"Rescan done" sent prematurely (before rescan is done!)
Last modified: 2011-03-16 04:39:20 UTC
I'm using svn r9739. My Lazy Search plugin is interested in the end of a music scan so it can process the database contents. It therefore registers interest during initPlugin() with: Slim::Control::Request::subscribe( \&Plugins::LazySearch2::scanDoneCallback, [ ['rescan'], ['done'] ] ); This used to work fine, but now I see that my plugin seems to be called before the database scan has finished. I saw this about a week ago but noticed a commit saying that there was a fix in the areas of timers and rescan and it appeared fixed, but it seems to have come back for me. I've attached my slimserver log showing: 1. SlimServer startup 2. The lazification that happens when my plugins initialised first-off (line 175). This *isn't* trigged by the rescan so can be ignored here. 3. The database clear-and-rescan being kicked off (around line 196). 4. My plugin being told rescan has finished (and consequently not finding the database contents to process) - line 204. The rest of the log shows the rescan proceeding (it's only a small test library), but my plugin never being called again. This was certainly working in the past, and was working since the split-scanner work was merged back in, so there's been some other change in the meantime. If there's any investigation you'd like me to do the just let me know.
Created attachment 1541 [details] Logfile of rescan behaviour
Any idea, Dan?
This change should have fixed it, as I was seeing the same issue.. http://svn.slimdevices.com/trunk/server/Slim/Music/Import.pm?rev=9611&r1=9560&r2=9611
I thought that, too (that's the commit I mentioned in the original report) - and I was definitely using a newer revision when I captured that log (attached). I tried several times and the behaviour (at the time), was consistent. Looking at the log attached (the entry dated 2006-09-15 14:05:29.6561), it looks like the subscription is called before the scanner registers that the scan is in progress (the "UPDATE metainformation SET value = ? WHERE ( name = ? ): '1', 'isScanning'" SQL). I wonder, then, if there's some race condition where the main process looks at the 'isScanning' metainformation before the scanner process has indicated that the scan is in progress? My system is quite slow (~450Mhz Gentoo Linux), and I may have had additional load on the server at the time. Trying again on my system now (which I've updated to r9790), I can't reproduce the problem, but that might be because of different server load, perhaps? I'm happy to try anything else, but it seems I can no longer recreate the problem. I've tried loading the CPU and disk but still cannot recreate the problem. I'm happy if you want to mark this bug as invalid (unless you think the race condition idea has some mileage). If so I'll request it be reopened if I see it again.
Fred - any thoughts here?
Well, from the code, if the scanner takes more than 30 secs to launch and init, the whole thing breaks. Why is the first check after 30s and the subsequent ones after 60 ? Doing the reverse may prevent this issue from happening if for whatever reason the OS has to swap a lot of memory around, f.e. OK LazySearch is doing stuff but in this example, there's 14 secs between the first "SlimServer OSDetect init..." to the "UPDATE metainformation SET value = ? WHERE ( name = ? ): '1', 'isScanning'"... It's not entirely clear from the log what is triggering the rescan when. Where does the "DELETE FROM playlist_track WHERE ( playlist = ? ): '99'" come from? You get the notification at 14:05:26 and there a check for isScanning exactly 30 seconds before in the log... ? I don't see a way for the notification to fire before it is being sent :-)
Dan's going to up the timeout value.
Dan's going to change the flag to not rely on the timer. This will help slow machines.
Thanks for the update - I'll watch for that change dropping in and will give it a test when it does.
Fixed in change 10070 Still using a timer, but this should be much better.
I've been running that change for a couple of days and have not seen the original problem despite a number of rescans. So, I think this resolves the issue I originally reported - thanks very much for the fix.
This bug has been fixed in the 7.3.0 release version of SqueezeCenter! Please download the new version from http://www.slimdevices.com/su_downloads.html if you haven't already. If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.