Bug 16142 - Scanner crashes repeatedly during directory scan, "Music scan terminated unexpectedly" error
: Scanner crashes repeatedly during directory scan, "Music scan terminated unex...
Status: RESOLVED WORKSFORME
Product: Logitech Media Server
Classification: Unclassified
Component: Scanner
: 7.5.x
: Infrant ReadyNAS RAIDiator x86
: -- major with 5 votes (vote)
: Investigating
Assigned To: Andy Grundman
: Audio::Scan
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2010-04-25 09:48 UTC by Dave Cowen
Modified: 2011-11-06 18:00 UTC (History)
2 users (show)

See Also:
Category: ---


Attachments
log from a bunch of failed scans (14.92 KB, text/plain)
2011-06-07 18:48 UTC, Jay Gee
Details
jpg of my terminated scan (100.65 KB, image/jpeg)
2011-06-07 18:52 UTC, Jay Gee
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Dave Cowen 2010-04-25 09:48:34 UTC
I upgraded to 7.5 from 7.3.4 on my ReadyNAS NVX using the wiki procedure (Clean DB, remove, install upgrade, clean DB again).  I had to revert because of severe problems with the scanner crashing.  7.3.4 works perfectly on the same library, even after a reinstall.

A full scan terminates with a "Music scan terminated unexpectedly (Directory Scan)" error after a couple of minutes of scanning in versions of Squeezebox Server >7.3.4.  This doesn't happen at a predefined point -- it randomly cuts out, perhaps after thousands of files scanned, perhaps three.  The last file scanned is different each time.  There doesn't appear to be a particular track or directory that it's having trouble with, and it doesn't appear related to a particular amount of time.

In the logs, there wasn't an error message specific to the crash, even with logging set to "Info."  It would merely say "scanner is not running, but no progress data available - scanner crashed."

Doing a Clean DB, remove, install of 7.3.4, clean DB and rescan allows me to successfully scan and play all of my music collection.

I'm running RAIDiator 4.2.9.

Music library stats:
Total Tracks: 26,632
Total Albums: 5,017
Total Artists: 3,335
Total Genres: 273

The following threads describe problems with 7.4.1 (which I also tried reverting to without success) that seem very similar to the ones I experienced, one on ReadyNAS, one not:

http://www.readynas.com/forum/viewtopic.php?f=22&t=34836
http://www.audionervosa.com/index.php?topic=1957.0

Let me know if there are specific tests/logs that would help on your side.
Comment 1 unixcrab 2010-07-30 04:11:42 UTC
I have the same setup except on a ReadyNAS DUO. Upgrading to 7.5.1 has caused the scanner to randomly, but always, crash. I've been through all the remove, re-install, clean routines but to no avail.

Log:

frame 10: Slim::Music::MusicFolderScan::init
(/usr/sbin/squeezeboxserver line 435)
  frame 11: main::init (/usr/sbin/squeezeboxserver line 578)
  frame 12: main::main (/usr/sbin/squeezeboxserver line 1072)

[10-07-25 20:50:49.0447] Slim::Schema::Storage::throw_exception (82)
Error: DBI Exception: DBD::mysql::st execute failed: Table
'slimserver.dbix_migration' doesn't exist [for Statement "SELECT value
FROM dbix_migration WHERE name = ?;
"]
[10-07-25 20:50:49.0540] Slim::Schema::Storage::throw_exception (82) Backtrace:

  frame 0: Slim::Utils::Log::logBacktrace
(/usr/share/perl5/Slim/Schema/Storage.pm line 82)
  frame 1: Slim::Schema::Storage::throw_exception
(/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 957)
  frame 2: DBIx::Class::Storage::DBI::__ANON__
(/usr/share/squeezeboxserver/lib/DBIx/Migration.pm line 237)
  frame 3: (eval) (/usr/share/squeezeboxserver/lib/DBIx/Migration.pm line 233)
  frame 4: DBIx::Migration::_version
(/usr/share/squeezeboxserver/lib/DBIx/Migration.pm line 78)
  frame 5: DBIx::Migration::migrate (/usr/share/perl5/Slim/Schema.pm line 480)
  frame 6: Slim::Schema::migrateDB (/usr/share/perl5/Slim/Schema.pm line 161)
  frame 7: Slim::Schema::init (/usr/share/perl5/Slim/Music/Import.pm line 744)
  frame 8: Slim::Music::Import::_checkLibraryStatus
(/usr/share/perl5/Slim/Music/Import.pm line 677)
  frame 9: Slim::Music::Import::useImporter
(/usr/share/perl5/Slim/Music/MusicFolderScan.pm line 48)
  frame 10: Slim::Music::MusicFolderScan::init
(/usr/sbin/squeezeboxserver line 435)
  frame 11: main::init (/usr/sbin/squeezeboxserver line 578)
  frame 12: main::main (/usr/sbin/squeezeboxserver line 1072)

[10-07-25 20:51:12.7087] main::checkDataSource (974) Warning: Schema
updated or no tracks in the database, initiating scan.
[10-07-25 20:51:18.2765] Slim::Schema::Storage::throw_exception (82)
Error: DBI Exception: DBD::mysql::st execute failed: MySQL server has
gone away [for Statement "SELECT me.name, me.value FROM
metainformation me WHERE ( name = ? )"]
[10-07-25 20:51:18.2877] Slim::Schema::Storage::throw_exception (82) Backtrace:

  frame 0: Slim::Utils::Log::logBacktrace
(/usr/share/perl5/Slim/Schema/Storage.pm line 82)
  frame 1: Slim::Schema::Storage::throw_exception
(/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 957)
  frame 2: DBIx::Class::Storage::DBI::__ANON__
(/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 1217)
  frame 3: DBIx::Class::Storage::DBI::_dbh_execute
(/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 547)
  frame 4: (eval)
(/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 540)
  frame 5: DBIx::Class::Storage::DBI::dbh_do
(/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 1227)
  frame 6: DBIx::Class::Storage::DBI::_execute
(/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 1451)
  frame 7: DBIx::Class::Storage::DBI::_select
(/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 1905)
  frame 8: DBIx::Class::Storage::DBI::select_single
(/usr/share/squeezeboxserver/CPAN/DBIx/Class/ResultSet.pm line 740)
  frame 9: DBIx::Class::ResultSet::single
(/usr/share/perl5/Slim/Schema.pm line 584)
  frame 10: Slim::Schema::single
(/usr/share/perl5/Slim/Music/Import.pm line 729)
  frame 11: Slim::Music::Import::stillScanning
(/usr/share/perl5/Slim/Music/Import.pm line 232)
  frame 12: Slim::Music::Import::checkScanningStatus
(/usr/share/perl5/Slim/Utils/Timers.pm line 255)
  frame 13: (eval) (/usr/share/perl5/Slim/Utils/Timers.pm line 255)
  frame 14: Slim::Utils::Timers::__ANON__
(/usr/share/perl5/Slim/Networking/IO/Select.pm line 183)
  frame 15: (eval) (/usr/share/perl5/Slim/Networking/IO/Select.pm line 183)
  frame 16: Slim::Networking::IO::Select::loop
(/usr/sbin/squeezeboxserver line 620)
  frame 17: main::idle (/usr/sbin/squeezeboxserver line 580)
  frame 18: main::main (/usr/sbin/squeezeboxserver line 1072)

[10-07-25 20:51:28.2687] Slim::Web::Graphics::processCoverArtRequest
(273) Error: Unable to resize
plugins/cache/icons/radiomusic_41x41_m.png (original file:
/var/lib/squeezeboxserver/cache/icons/radiomusic.png): Can't call
method "width" on an undefined value at
/usr/share/perl5/Slim/Utils/ImageResizer.pm line 139.
[10-07-25 20:52:58.7145] Slim::Utils::Firmware::downloadAsyncError
(557) Warning: Firmware: Failed to download
http://update.mysqueezebox.com/update/firmware/7.5.1/jive_7.5.1_r8885.bin.sha
(Connect timed out: Inappropriate ioctl for device), will try again in
10 minutes.
[10-07-25 20:56:09.0854] Slim::Networking::SqueezeNetwork::_error
(471) Unable to login to SN: Invalid mysqueezebox.com username or
password.
Comment 2 Dave Cowen 2010-12-24 18:38:35 UTC
This issue persists with Squeezebox Server 7.5.2 - r31632 on Radiator 4.2.15 for ReadyNAS NVX.  Squeezebox Server 7.3.4 continues to scan without difficulty.

This is especially disappointing, as we just picked up a Squeezebox Radio to complement our two Booms and Duet -- but it won't work with Squeezebox Server 7.3.4.  That essentially makes the Squeezebox Radio a paperweight, as we're caught in a Catch-22 of it requiring a version of Squeezebox Server that can't complete a directory scan on our NVX.  (The Booms and Duet continue to work without difficulty with 7.3.4.)

The specific error is: Music scan terminated unexpectedly (Directory Scan)

Log entries:

[10-12-24 18:18:58.4691] Slim::Schema::init (147) Warning: Creating new database - empty database or database from 6.3.x found
[10-12-24 18:18:58.4725] Slim::Schema::Storage::throw_exception (82) Error: DBI Exception: DBD::mysql::st execute failed: Table 'slimserver.dbix_migration' doesn't exist [for Statement "SELECT value FROM dbix_migration WHERE name = ?;
" with ParamValues: 0='version']
[10-12-24 18:18:58.5830] Slim::Schema::Storage::throw_exception (82) Backtrace:

   frame 0: Slim::Utils::Log::logBacktrace (/usr/share/perl5/Slim/Schema/Storage.pm line 82)
   frame 1: Slim::Schema::Storage::throw_exception (/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 957)
   frame 2: DBIx::Class::Storage::DBI::__ANON__ (/usr/share/squeezeboxserver/lib/DBIx/Migration.pm line 237)
   frame 3: (eval) (/usr/share/squeezeboxserver/lib/DBIx/Migration.pm line 233)
   frame 4: DBIx::Migration::_version (/usr/share/squeezeboxserver/lib/DBIx/Migration.pm line 149)
   frame 5: DBIx::Migration::version (/usr/share/perl5/Slim/Schema.pm line 478)
   frame 6: Slim::Schema::migrateDB (/usr/share/perl5/Slim/Schema.pm line 161)
   frame 7: Slim::Schema::init (/usr/share/perl5/Slim/Music/Import.pm line 744)
   frame 8: Slim::Music::Import::_checkLibraryStatus (/usr/share/perl5/Slim/Music/Import.pm line 677)
   frame 9: Slim::Music::Import::useImporter (/usr/share/perl5/Slim/Music/MusicFolderScan.pm line 48)
   frame 10: Slim::Music::MusicFolderScan::init (/usr/sbin/squeezeboxserver line 435)
   frame 11: main::init (/usr/sbin/squeezeboxserver line 578)
   frame 12: main::main (/usr/sbin/squeezeboxserver line 1072)

[10-12-24 18:18:58.6111] Slim::Schema::Storage::throw_exception (82) Error: DBI Exception: DBD::mysql::st execute failed: Table 'slimserver.dbix_migration' doesn't exist [for Statement "SELECT value FROM dbix_migration WHERE name = ?;
" with ParamValues: 0='version']
[10-12-24 18:18:58.6120] Slim::Schema::Storage::throw_exception (82) Backtrace:

   frame 0: Slim::Utils::Log::logBacktrace (/usr/share/perl5/Slim/Schema/Storage.pm line 82)
   frame 1: Slim::Schema::Storage::throw_exception (/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 957)
   frame 2: DBIx::Class::Storage::DBI::__ANON__ (/usr/share/squeezeboxserver/lib/DBIx/Migration.pm line 237)
   frame 3: (eval) (/usr/share/squeezeboxserver/lib/DBIx/Migration.pm line 233)
   frame 4: DBIx::Migration::_version (/usr/share/squeezeboxserver/lib/DBIx/Migration.pm line 78)
   frame 5: DBIx::Migration::migrate (/usr/share/perl5/Slim/Schema.pm line 480)
   frame 6: Slim::Schema::migrateDB (/usr/share/perl5/Slim/Schema.pm line 161)
   frame 7: Slim::Schema::init (/usr/share/perl5/Slim/Music/Import.pm line 744)
   frame 8: Slim::Music::Import::_checkLibraryStatus (/usr/share/perl5/Slim/Music/Import.pm line 677)
   frame 9: Slim::Music::Import::useImporter (/usr/share/perl5/Slim/Music/MusicFolderScan.pm line 48)
   frame 10: Slim::Music::MusicFolderScan::init (/usr/sbin/squeezeboxserver line 435)
   frame 11: main::init (/usr/sbin/squeezeboxserver line 578)
   frame 12: main::main (/usr/sbin/squeezeboxserver line 1072)
Comment 3 Ben Strulo 2011-04-21 09:46:36 UTC
I'm seeing exactly the same symptoms though on Windows XP.  Seems likely to be the same bug, but I'm not completely certain so maybe I should raise a new one?

My problems are described here:

http://forums.slimdevices.com/showthread.php?t=86962

I am seeing the bug with a couple of versions of 7.5.4 including the release.  I don't know how far back I would need to go to find one that works, but it used to work, for example, I think 7.3 used to work fine.

The place it crashes appears to be random and once it even got all the way through.

This is on "clear library and rescan everything".
Comment 4 Ben Strulo 2011-04-22 01:07:43 UTC
(In reply to comment #3)
> I'm seeing exactly the same symptoms though on Windows XP.  Seems likely to be
> the same bug, but I'm not completely certain so maybe I should raise a new one?

OK, mine perhaps isn't the same bug, since in my case it is definitely fixed by downgrading to 7.5.2

I've raised a separate bug report: 17173
Comment 5 Andy Grundman 2011-04-25 09:15:46 UTC
Need more details.
Comment 6 Dave Cowen 2011-04-25 09:42:07 UTC
(In reply to comment #5)
> Need more details.

Hi, Andy --

Thanks for taking this bug.  I'd be happy to provide any diagnostic information that you'd like.  Please specify any log file information that I didn't provide that might be useful, or diagnostic procedures you'd like me to follow.

Dave
Comment 7 Jay Gee 2011-06-07 18:48:41 UTC
Created attachment 7311 [details]
log from a bunch of failed scans

I ran the scanner 5 times, each time, removing files/folders that appeared to bork the scan.
Comment 8 Jay Gee 2011-06-07 18:50:33 UTC
Andy,

Trevor (T2 Support) recommended I contact you with my issue as it may be exactly the same as this bug.  My situation is as follows:

When using 7.5.2 or 7.5.4 (I have not tried 7.5.1 or 7.5.3) the scanner cannot perform a complete scan of my library on ReadyNAS+.  Important: for me, the scanner always works flawlessly on 7.5.0, just not on later 7.5.x versions.

On 7.5.2 and 7.5.4, the scanner aborts with the "terminated unexpectedly" error no more than 1% into the scan.  It *looks* like the scan fails when it gets to a filename/directory that it has trouble with.  Included as an attachment are the notes from my various scan attempts.  As you can see, I remove some potentially difficult directory names, and the scan often gets passed that point, but fails again quickly.  Based on various forum threads, I've read, it seems like something broke in 7.5.1.

Now this bug specifies "7.5.x" as the version.  Dave Cowen says at the top of the bug:
> I upgraded to 7.5 from 7.3.4 on my ReadyNAS NVX using the wiki procedure (Clean
> DB, remove, install upgrade, clean DB again).  I had to revert because of
> severe problems with the scanner crashing.  7.3.4 works perfectly on the same
> library, even after a reinstall.


Do we know if he means 7.5.0?  If he does, then we have a different problem since 7.5.0 *works* for me.  If he means 7.5.1 or above, then we're talking about the same problem.  Assuming some restriction was introduced in 7.5.1 and has still not been fixed, can we:

1) Identify the change that was made and revert it?  or 
2) Change the scanner code so that if it chokes on a file, it simply skips that file and continues?  <--- this seems like behavior you'd want anyway, right?  Then you could report: "Scan Completed, the following x directories couldn't be parsed; the following y files couldn't be parsed;"

Please let me know how I can help.

Thanks,

-jg
Comment 9 Jay Gee 2011-06-07 18:52:04 UTC
Created attachment 7312 [details]
jpg of my terminated scan
Comment 10 Jay Gee 2011-06-07 18:53:42 UTC
*** This bug has been confirmed by popular vote. ***
Comment 11 Jay Gee 2011-06-14 18:06:43 UTC
Forget it.

Even though it's not the *right* way to do it, I've decided to run 7.5.4 (with the 7.5.3 scanner) on the PC.  The ReadyNAS NV+ with 256Mb is just underpowered to serve my library.  SBS is about 10x faster (in every respect) on my 6 year-old PC.  Go figure.  For details see:
  http://forums.slimdevices.com/showthread.php?p=636401#post636401

Thanks, anyway.

-jg
Comment 12 Dave Cowen 2011-06-15 07:32:37 UTC
Hi, Jay --

I'm the original individual who compiled this ticket, and who is still stuck on SqueezeCenter 7.3.4 because of the similar scan problems that we've both experienced with the later versions.

While the NV+ may well be slow, the newer ReadyNAS NVX (and the x86 versions of ReadyNAS released since) runs SqueezeCenter 7.3.4 very well.  So, I'm still hoping that Logitech will one day wake up and pay attention to this issue.

Andy from SlimDevices --

Both Jay and I have posted quite a bit of diagnostic information, and I've offered to provide whatever you need to help troubleshoot this issue -- but you never wrote back after you said "Need more details."  If you could clarify what you need, I'd be happy to get you that information.

Dave
Comment 13 Andy Grundman 2011-09-19 06:57:29 UTC
Please retest with the latest nightly, and enable scan.scanner logging. If you find a specific file that causes this, please send it to me: http://wiki.slimdevices.com/index.php/Large_File_Upload
Comment 14 Dave Cowen 2011-11-06 18:00:29 UTC
Well, I'll be.  I got back from an extended vacation, saw your e-mail, and by that time, Logitech Media Server 7.7 had been released.  Thankfully, 7.7 will now scan (short of a handful of problem MP3s) the entire collection on my ReadyNAS NVX. 

As above, I did find a few files which caused it to stall, but these failures were obvious and logged in a way I could hunt down the files.  7.4 through 7.6 would fail at seemingly arbitrary points, and rarely on the same file.  

I'll upload some of the problematic MP3s in the near future.  

Andy, I'm extremely encouraged by the assortment of releases in the past few months, and that you've been watching this ticket.