Bug 17452 - 7.6.1-r33094 (aka RC1) internal scanner broken when deleting tracks
: 7.6.1-r33094 (aka RC1) internal scanner broken when deleting tracks
Status: RESOLVED FIXED
Product: Logitech Media Server
Classification: Unclassified
Component: Database
: 7.6.0
: PC Ubuntu Linux
: P1 critical with 4 votes (vote)
: 7.6.x
Assigned To: Andy Grundman
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2011-08-15 09:51 UTC by Ian Pallfreeman
Modified: 2011-10-10 18:09 UTC (History)
3 users (show)

See Also:
Category: ---


Attachments
leading spaces are breaking textkeys (6.96 KB, image/png)
2011-08-15 21:53 UTC, Michael Herger
Details
Figure 1: Deleting tracks that are actually removed (61.63 KB, image/jpeg)
2011-09-23 00:46 UTC, Magnar Strand Olsen
Details
Figure 2: Now we're done deleting the removed tracks, and stuck in a rot... (60.97 KB, image/jpeg)
2011-09-23 00:47 UTC, Magnar Strand Olsen
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Ian Pallfreeman 2011-08-15 09:51:58 UTC
http://forums.slimdevices.com/showthread.php?t=89450&page=19

An SBS installation (r33033, r33044) upgraded to r33094 will not complete a new/changed scan. It gets stuck deleting (imaginary) files.

Front page shows:

 Rescanning Music Library... Removing deleted files  (16551 of 283)

and the number just keeps climbing. 

Verified on FreeBSD i386/amd64 and Ubuntu.
Comment 1 Michael Herger 2011-08-15 10:47:45 UTC
Is it only the display on the front page going wrong, or is the scan indeed stuck?
Comment 2 Andy Grundman 2011-08-15 10:48:36 UTC
Hmm I can't reproduce this. Can you provide more details? Here is what I tried:

Full scan on directory of 129 files.
Moved all those files to a subdirectory called 'copy'.
Rescan deleted 129 files correctly, then scanned 129 new files.
Comment 3 Ian Pallfreeman 2011-08-15 11:16:08 UTC
You can glean more details from my inane babblings in the forum. 

Basically, I'm updating all my test boxes to the RC (or better). They're running various post-WAL versions. Stop SBS, install new version, restart SBS. None of them have completed a new/changed scan, they all get stuck deleting these imaginary files.

I'm still waiting for a full scan to complete on another box. That may be OK.

The new/changed scan is stuck for sure, eating 100% of a CPU. The Information display shows the same filename throughout. 

They're all scanning the same collection, which hasn't changed for several days. 

Friday's r33073 is fine. 

What else can I provide as evidence? I confess I thought it was something weird with my FreeBSD builds, which is why also checked with Ubuntu. Same problem.
Comment 4 Ian Pallfreeman 2011-08-15 11:33:02 UTC
Watching the Information display, the "Removing deleted files" line starts off normally with (N of X) then changes to just (X):

Music Scan Details
Discovering files/directories: /music   (201890 of 201890)   Complete  00:01:32 
 
Removing deleted files: /music   (8101)   Running  00:05:11 

/music/A/A Dark Halo - Catalyst/cover.jpg

Abort scan

Top:

top - 19:31:37 up  2:42,  3 users,  load average: 1.26, 0.92, 0.49
Tasks: 172 total,   2 running, 170 sleeping,   0 stopped,   0 zombie
Cpu(s): 48.3%us,  1.8%sy,  0.0%ni, 49.3%id,  0.5%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   2060428k total,  1964588k used,    95840k free,   142544k buffers
Swap:  3227640k total,        0k used,  3227640k free,  1311300k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND           
 2449 squeezeb  20   0  131m 122m 5020 R  100  6.1   8:03.71 squeezeboxserve    
 2549 ip        20   0  2548 1216  904 R    0  0.1   0:00.04 top
Comment 5 Ian Pallfreeman 2011-08-15 11:48:48 UTC
http://virgin.xenopsyche.net:9000

Just opened port 9000 in my cable NAT box. Redirected to the box currently running Ubuntu (and showing the problem). 

Note .net not .com.
Comment 6 Ian Pallfreeman 2011-08-15 16:30:07 UTC
My full scan completed OK. A subsequent rescan exhibits the same problem. That's my day gone. 

I think I know what's causing this. 

Every night a scheduled rescan says it's deleting about 180 files from the db. Has done for ages. Even if nothing has changed. The latest SBS is also trying to delete these same ~180 files, and that's where it's acting up. 

A few weeks ago I posted in the forum about .jpeg files appearing in my playlists, because my scripts didn't know better. Maybe I should fix the playlist which happens to contain about ~180 images...
Comment 7 Michael Herger 2011-08-15 21:53:42 UTC
Created attachment 7397 [details]
leading spaces are breaking textkeys

Thanks Ian!

Andy - from the web UI it seems that textkey generation is not cleaning up leading spaces? See the screenshot: an artist " 5..." leads to a spacer in the page bar
Comment 8 Ian Pallfreeman 2011-08-16 02:17:26 UTC
Thanks for looking at this for me, guys. I can confirm that a full scan after removing the images from the playlist prevents this horrible little bug during a subsequent rescan. Phew. For a moment there I thought I was going to have to call Logitech support. 

And yes, my tagging is atrocious. Even with hundreds of lines of carefully crafted heuristics, there's only so much one can do with an untagged album which is missing two tracks. I blame Usenet. 

Mark this one as a corner case or user error and close it?
Comment 9 Charles Razzell 2011-09-05 19:02:23 UTC
I've twice caught my post 7.6.1 release SBS installations in this mode of deleting files from the database that are still there in reality. It's very alarming to see messages about music files being deleted, when no deletions have taken place! 

I found there was no easy way to recover control except stopping SBS and killing processes. This happened once on a Vortexbox (FC14) with the released SBS 7.6.1 and once on a LinkStation with the NOCPAN tarball installed under SSODS.

If I actually do delete some music files, the detection seems to work as it should and the database updates accordingly. But it seems possible to trigger a 'phantom delete' scenario where SBS thinks files have gone away, and starts an infinite loop of deletions. I don't know how to reproduce this, but thought I should mention I've seen it happen a couple of times.
Comment 10 Magnar Strand Olsen 2011-09-23 00:39:30 UTC
*** This bug has been confirmed by popular vote. ***
Comment 11 Magnar Strand Olsen 2011-09-23 00:46:41 UTC
Created attachment 7473 [details]
Figure 1: Deleting tracks that are actually removed
Comment 12 Magnar Strand Olsen 2011-09-23 00:47:31 UTC
Created attachment 7474 [details]
Figure 2: Now we're done deleting the removed tracks, and stuck in a rot...
Comment 13 Magnar Strand Olsen 2011-09-23 00:51:59 UTC
I'm seeing the same thing. I've attached two screenshots from the scanner process.
Comment 14 Magnar Strand Olsen 2011-09-23 00:55:17 UTC
My server version is 7.6.2 - r33449 running on a Debian 64 bit server, by the way.
Comment 15 Michael Herger 2011-10-10 03:40:22 UTC
Is anyone of you using flac files and/or cue sheets?

Andy - from looking at the code I see we're only checking for songs, playlists or cue sheets. If there's any other entry in the table, it would be selected over and over again, right? I see eg. that the content-type 'cur' (whatever it is) wouldn't trigger any of these three conditions.

I've been able to reproduce this issue with the folder from https://svn.slimdevices.com/repos/slim/7.7/trunk/tests/data/bugs/bug2335. I had it in my scanned folder, then removed it. Upon next rescan the scanner got stuck at the removing step. Further narrowing down it indeed does not handle the track, as it's not recognized as neither song nor cue sheet nor playlist (it's considered a container). Maybe we should remove those entries from the DB even if they're not handled?
Comment 16 Mikael Nyberg 2011-10-10 03:41:56 UTC
I see this of lately this can happen when the scanner really has crashed, for example a dB lockeck error . then it continues to count forever .
Comment 17 SVN Bot 2011-10-10 03:50:29 UTC
 == Auto-comment from SVN commit #33588 to the slim repo by mherger ==
 == http://svn.slimdevices.com/slim?view=revision&revision=33588 ==

Bug: 17452
Description: don't always query deleted tracks from the first item, but keep track how many we've already handled
Comment 18 Michael Herger 2011-10-10 03:53:25 UTC
Ok, while what I tried to describe was triggering the event, the reason we ended up in a loop was much simpler. I hope this is fixed now. I'll push out new builds - please give them a try (r33588 or later).
Comment 19 Magnar Strand Olsen 2011-10-10 08:16:27 UTC
Will you be releasing a new 7.6.2 build with this bugfix as well?
Comment 20 Michael Herger 2011-10-10 08:54:29 UTC
What I considered a fix actually isn't. It will need some more work.
Comment 21 SVN Bot 2011-10-10 17:48:17 UTC
 == Auto-comment from SVN commit #33592 to the slim repo by agrundman ==
 == http://svn.slimdevices.com/slim?view=revision&revision=33592 ==

Bug 17452, revert r33588, needs to be fixed another way
Comment 22 SVN Bot 2011-10-10 18:06:45 UTC
 == Auto-comment from SVN commit #33593 to the slim repo by agrundman ==
 == http://svn.slimdevices.com/slim?view=revision&revision=33593 ==

Fixed bug 17452, handle deleted cur/fec track entries to avoid running the deleted phase forever