I am running the nightlies, by the way.

please attach a sample song file for review.

Created attachment 6775 [details]
Sample song which does not scan

Yep, here's a broken one (also a good tune, enjoy!). Interestingly not all songs in the same album (so from the same rip) are broken. Probably about 30-40% of my music fails to scan in this way.

Created attachment 6777 [details]
working here.

This is a capture of the scan results shown via browse.  I did not encounter any issues while using the 7.6 version (same as 7.5 embedded).  Either the problem is fixed in newer code or there is an issue on your system.

The error message you are seeing results from either the file being unreadable or the tag headers being corrupt.  Check the permissions on the problem files.  Make sure that they are readable for squeezeboxserver user.

Hello,

I'm here to provide an update on this, since I just got a new Radio and had to finally update from 7.4.

Now running r31915.

Lots and lots of songs still fail to scan. Here's a log excerpt.

[11-02-18 09:13:24.5514] Slim::Utils::Scanner::Local::new (634) Handling new track file:///home/laney/Music/Eva%20Cassidy/Time%20After%20Time/05.%20Time%20After%20Time.mp3
[11-02-18 09:13:24.5519] Slim::Utils::Misc::msg (1212) Warning: [09:13:24.5518] buffer_get_ret: trying to get more bytes 4 than in buffer 0 at /usr/share/squeezeboxserver/CPAN/Audio/Scan.pm line 64.
[11-02-18 09:13:24.5521] Slim::Formats::readTags (178) Error: While trying to ->getTag(/home/laney/Music/Eva Cassidy/Time After Time/05. Time After Time.mp3) : buffer_get_int_le: buffer error at /usr/share/squeezeboxserver/CPAN/Audio/Scan.pm line 64.
[11-02-18 09:13:24.5524] Slim::Formats::readTags (178) Backtrace:

   frame 0: Slim::Utils::Log::logBacktrace (/usr/share/perl5/Slim/Formats.pm line 178)
   frame 1: Slim::Formats::readTags (/usr/share/perl5/Slim/Schema.pm line 1486)
   frame 2: Slim::Schema::_newTrack (/usr/share/perl5/Slim/Schema.pm line 1819)
   frame 3: Slim::Schema::updateOrCreateBase (/usr/share/perl5/Slim/Utils/Scanner/Local.pm line 645)
   frame 4: Slim::Utils::Scanner::Local::__ANON__ (/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 638)
   frame 5: (eval) (/usr/share/squeezeboxserver/CPAN/DBIx/Class/Storage/DBI.pm line 627)
   frame 6: DBIx::Class::Storage::DBI::txn_do (/usr/share/squeezeboxserver/lib/DBIx/Class/Schema.pm line 650)
   frame 7: DBIx::Class::Schema::txn_do (/usr/share/perl5/Slim/Utils/Scanner/Local.pm line 705)
   frame 8: Slim::Utils::Scanner::Local::new (/usr/share/perl5/Slim/Utils/Scanner/Local.pm line 307)
   frame 9: Slim::Utils::Scanner::Local::__ANON__ (/usr/share/perl5/Slim/Utils/Scheduler.pm line 150)
   frame 10: (eval) (/usr/share/perl5/Slim/Utils/Scheduler.pm line 150)
   frame 11: Slim::Utils::Scheduler::run_tasks (/usr/sbin/squeezeboxserver line 667)
   frame 12: main::idle (/usr/sbin/squeezeboxserver line 634)
   frame 13: main::main (/usr/sbin/squeezeboxserver line 1129)

[11-02-18 09:13:24.5525] Slim::Utils::Scanner::Local::__ANON__ (654) ERROR SCANNING file:///home/laney/Music/Eva%20Cassidy/Time%20After%20Time/05.%20Time%20After%20Time.mp3: Unable to read tags from file

I removed ID3v1 and v2 tags from this file and it still failed to scan in the same way.

Hi,

I have got exactly the same problem as Iain Lane.
I'm running Squeezebox Server Version: 7.5.4 - r32171 @ Thu Apr 14 09:19:34 PDT 2011 on Windows XP SP3.

The problem is definitely not an access right problem, but related to certain conditions in the tags.
It can be fixed with MP3Tag in the following way:
1. Copy Tag
2. Remove Tag
3. Paste Tag
After this procedure the file with all its tags is scanned properly.
However it is practically impossible to go through this exercise with hundreds of files that are not recognised properly (about 50 percent of my files).

Squeezebox scanner is the only program that fails reading the original files/tags. None of the other applications that I use have a problem. This includes WinAmp, MediaMonkey, MP3Val, MP3Tag. They are all showing the tags without any error messages or difficulties.
So squeezebox scanner should be able to cope with it as well.

Could you please have a look. I can provide an example file if necessary.

Best Regards, Jürgen

I see the same problem and have been seeing it for quite a while in both 7.5 and 7.6. I'm running SBS on a Windows server, not Ubuntu.

When a clear & rescan is run, anywhere from 900-1300 files in my library are skipped, with 'Unable to read tags from file' errors being logged to scanner.log. There's no sense in uploading any of the files, because each time the scan is run, it's a different number and a different set of files. There is nothing wrong with the files.

Running subsequent new & changed scans eventually picks up all of the missed files. It usually takes two or three additional new & changed scans to get them all.

The problem on my system is only with Flac files. Mp3 files are scanned 100%, with no errors.

Tonight I ran some additional tests. I have an Mp3 library that is a mirror of my Flac library. And I backup both the Flac and Mp3 libraries to an external USB drive. Trying to eliminate the possibility that the file errors were disk related, I set up two new 7.6 servers, one pointing at the backup Flac library, and one pointing at the backup Mp3 library, both on the USB drive.

The initial scan of the Mp3 library was 100%.

The initial scan of the Flac library skipped 971 files. Running a subsequent new & changed scan correctly scanned 947 of those files, and logged 24 'Unable to read tags from file' errors in server.log. A second new & changed scan picked up 20 of the 24, and a third try picked up the remaining 4 files.

Created attachment 7328 [details]
zipped scanner.log

Here's a scanner.log for a clear & rescan of the Flac library with all scan.x logging set to debug. It scanned 30976 of 32338 files, so there should be 1362 'Unable to read tags from file' errors.

Looks like the errors are due to:
[11-07-01 20:40:05.2629] Audio::Scan::scan (64) Warning: Error reading: No error (wanted 4096)

This comes from the following code in common.c:

 if ( (read = PerlIO_read(infile, tmp, actual_wanted)) <= 0 ) {
      if ( PerlIO_error(infile) ) {
        warn("Error reading: %s (wanted %d)\n", strerror(errno), actual_wanted);
      }
      else {
        warn("Error: Unable to read at least %d bytes from file.\n", min_wanted);
      }

      ret = 0;
      goto out;
    }

Is it possible that PerlIO_read is returning due to being interrupted by a signal and we are treating this as an error erroneously?  Don't know why errono is not set though - do we need to use GetLastError or is it reset by the PerlIO_error call?

Looks like Jim's problem is different from the one at the start of this bug.

Jim's problem looks to be due to windows error 1450 - "Insufficient system resources exist to complete the requested service.  Hopefully some tuning of his server will make this go away."  (see http://support.microsoft.com/kb/304101/en-us)

We should add something to log the response from GetLastError on windows as the low level perl code uses ReadFile and this doesn't appear to set errno.

If tuning does not help Jim, then we may need to back off scanning for a few ms if we get that error?

Thanks for debugging this, I'll see about building a version with Triode's patch. *insert random Windows-related grumbling here*

Hi all,

I agree with Adrian that Jim's Problem is slightly different from the one that this bug originally related to.
There is no random behaviour in the way the scan fails with my audio files.
It is always the same set of files that is not scanned.

The log entry is always the same as well and looks like this:

[11-06-03 20:52:41.7063] Audio::Scan::scan (64) Warning: buffer_get_ret: trying to get more bytes 4 than in buffer 0 at /<C:\PROGRA~1\SQUEEZ~1\server\scanner.exe>Audio/Scan.pm line 64.
[11-06-03 20:52:41.7066] Slim::Formats::readTags (178) Error: While trying to ->getTag(C:\Documents and Settings\jmayerho\My Documents\JM\Music\Play\Moods\Fast\Adventurous\Chequered Love\Shakira - Suerte (Whenever, Wherever).mp3) : buffer_get_int_le: buffer error at /<C:\PROGRA~1\SQUEEZ~1\server\scanner.exe>Audio/Scan.pm line 64.
[11-06-03 20:52:41.7069] Slim::Formats::readTags (178) Backtrace:

   frame 0: Slim::Utils::Log::logBacktrace (/<C:\PROGRA~1\SQUEEZ~1\server\scanner.exe>Slim/Formats.pm line 178)
   frame 1: Slim::Formats::readTags (/<C:\PROGRA~1\SQUEEZ~1\server\scanner.exe>Slim/Schema.pm line 937)
   frame 2: Slim::Schema::newTrack (/<C:\PROGRA~1\SQUEEZ~1\server\scanner.exe>Slim/Utils/Scanner.pm line 347)
   frame 3: Slim::Utils::Scanner::scanDirectory (/<C:\PROGRA~1\SQUEEZ~1\server\scanner.exe>Slim/Music/MusicFolderScan.pm line 79)
   frame 4: Slim::Music::MusicFolderScan::startScan (/<C:\PROGRA~1\SQUEEZ~1\server\scanner.exe>Slim/Music/Import.pm line 568)
   frame 5: Slim::Music::Import::runImporter (/<C:\PROGRA~1\SQUEEZ~1\server\scanner.exe>Slim/Music/Import.pm line 373)
   frame 6: Slim::Music::Import::runScan (scanner.pl line 305)
   frame 7: (eval) (scanner.pl line 299)
   frame 8: main::main (scanner.pl line 454)

@ Adrian, Andy:
While you are looking at Jim's problem, would it be possible to look at the original problem that Ian and I had as well? I would very much appreciate this as I can only play half of my files using Squeezebox Server.

Best Regards, Jürgen

I've tested the file attached by Ian with both Linux and Windows and I can scan in both cases with the latest 7.6.  Can you confirm you are still seeing the problem and attach a file with the problem if it is different from the one attached here.

 == Auto-comment from SVN commit #32706 to the slim repo by agrundman ==
 == http://svn.slimdevices.com/slim?view=revision&revision=32706 ==

Bug 15895, Rebuilt Audio::Scan 0.87 with Triode's Windows error message patch

Please let me know if this helps, guys.

Created attachment 7333 [details]
Song that fails to scan.

Hi Adrian,

I just scanned my files with the latest version of Squeezebox Server:
   Version: 7.5.5 - r32671 @ Mon Jul 11 12:00:49 PDT 2011

The problem still exists.
Please find attached one of the files that fail to scan (the Shakira song that produced the error log entry that I posted in one of my previous comments).

Thanks for your help.
Jürgen

Andy - this file does cause a problem.  It looks to be due to ape field parsing running off the end of the buffer.  I don't understand at present where the code checks that it has enough buffered data to read all the ape fields - perhaps you could look.  Here's the debug output with a backtrace at the point the error occurs:

adrian@mac:~/squeezecenter/Audio-Scan$ ./test.pl
problem.mp3
Buffer allocated with 4096 bytes
Buffering from file @ 0 (min_wanted 10, max_wanted 4096, adjusted to 4096)
Buffered 4096 bytes, new pos 4096
Found ID3v2.3.0 tag, size 9201
  seeked past 9201 bytes to 9201
Buffering from file @ 9201 (min_wanted 4, max_wanted 4096, adjusted to 4096)
Buffered 4096 bytes, new pos 13297
Found FF sync at offset 9201
Frame @9c06a3c: size=417, 1152 samples, 128kbps 44100/2
Frame @9c06bdd: size=417, 1152 samples, 128kbps 44100/2
Frame @9c06d7e: size=418, 1152 samples, 128kbps 44100/2
  valid frame
Found Xing/Info tag
bitrate from lame_abr_rate: 128
ID3v1 tag found
Buffer high water mark: 4096
Seeked to 3125840 looking for APE tag
Buffer allocated with 136 bytes
Buffering from file @ 3125840 (min_wanted 136, max_wanted 136, adjusted to 136)
Buffered 136 bytes, new pos 3125976
APE tag found at -160 (with ID3v1)
Buffer high water mark: 136
Buffer allocated with 32 bytes
Buffering from file @ 3125840 (min_wanted 32, max_wanted 32, adjusted to 32)
Buffered 32 bytes, new pos 3125872
Found APEv2 tag, size 8310 with 13 items
APE tag offset 3117562
Buffer allocated with 32 bytes
Buffer allocated with 8246 bytes
Buffering from file @ 3117562 (min_wanted 32, max_wanted 32, adjusted to 32)
Buffered 32 bytes, new pos 3117594
Buffering from file @ 3117594 (min_wanted 8246, max_wanted 8246, adjusted to 8246)
Buffered 8246 bytes, new pos 3125840
Reduced audio_size value by APE/Lyrics2 tag size 8310
key_length: 14 / val_length: 8 / size: 7 / flags 0 @ 3117617
  MP3GAIN_MINMAX = 123,203
key_length: 12 / val_length: 12 / size: 11 / flags 0 @ 3117645
  MP3GAIN_UNDO = +006,+006,N
key_length: 21 / val_length: 13 / size: 12 / flags 0 @ 3117686
  REPLAYGAIN_TRACK_GAIN = -0.210000 dB
key_length: 21 / val_length: 9 / size: 8 / flags 0 @ 3117728
  REPLAYGAIN_TRACK_PEAK = 0.505601
key_length: 6 / val_length: 8 / size: 7 / flags 0 @ 3117751
  ARTIST = Shakira
key_length: 5 / val_length: 16 / size: 15 / flags 0 @ 3117772
  ALBUM = Laundry Service
key_length: 5 / val_length: 28 / size: 27 / flags 0 @ 3117801
  TITLE = Suerte (Whenever, Wherever)
key_length: 5 / val_length: 3 / size: 2 / flags 0 @ 3117842
  TRACK = 12
key_length: 4 / val_length: 5 / size: 4 / flags 0 @ 3117857
  YEAR = 2000
key_length: 5 / val_length: 6 / size: 5 / flags 0 @ 3117875
  GENRE = latin
key_length: 17 / val_length: 9 / size: 7934 / flags 2 @ 3117906
buffer_get_ret: trying to get more bytes 4 than in buffer 0 at blib/lib/Audio/Scan.pm line 64.
Obtained 10 stack frames.
./blib/arch/auto/Audio/Scan/Scan.so(buffer_get_int_le+0x54) [0xb749b884]
./blib/arch/auto/Audio/Scan/Scan.so(_ape_parse_field+0x35) [0xb749ca65]
./blib/arch/auto/Audio/Scan/Scan.so(_ape_parse_fields+0x38) [0xb749d1e8]
./blib/arch/auto/Audio/Scan/Scan.so(_ape_parse+0x59) [0xb74ab569]
./blib/arch/auto/Audio/Scan/Scan.so(+0x1f5f6) [0xb74ab5f6]
./blib/arch/auto/Audio/Scan/Scan.so(get_mp3tags+0x68) [0xb74c0418]
./blib/arch/auto/Audio/Scan/Scan.so(XS_Audio__Scan__scan+0x7e1) [0xb74b7f01]
/usr/bin/perl(Perl_pp_entersub+0x52b) [0x80d198b]
/usr/bin/perl(Perl_runops_standard+0x18) [0x80cfd58]
/usr/bin/perl(perl_run+0x342) [0x8078b22]
buffer_get_int_le: buffer error at blib/lib/Audio/Scan.pm line 64.

OK those types of problems are easy to deal with.

It might be good to know which application tagged this file. It's interesting that I can retag the file in Mp3tag, keeping the APE tag, and SBS will scan it OK. So it's not simply because the file has an APE tag, but something specific about how it's being written to the file.

FWIW, I've suspected that the scanner crashing problems being widely reported may also be due to APE tag handling. There seems to be some anecdotal evidence of this in the reports being made within the forums.

This is not a crash though, just a song that is not scanned because of a (possibly) invalid tag.

Right. I'm just saying that I think problems with the handling of APE tags may go beyond just this case. Once this bug is fixed, maybe it would be helpful to ask users with crashing problems to test the new scanner. Or when you fix this bug, perhaps look a bit more closely at overall APE tag handling and see if you can discover any other issues.

This problem file seems to claim more tag items than exist, I can parse the file with the following patch:

Index: src/ape.c
===================================================================
--- src/ape.c   (revision 867)
+++ src/ape.c   (working copy)
@@ -161,7 +161,7 @@
   tag->size         = buffer_get_int_le(&tag->tag_footer);
   tag->item_count   = buffer_get_int_le(&tag->tag_footer);
   tag->footer_flags = buffer_get_int_le(&tag->tag_footer);
-  tag->size += APE_TAG_FOOTER_LEN;
+  tag->size += APE_TAG_HEADER_LEN;
   data_size = tag->size - APE_TAG_HEADER_LEN - APE_TAG_FOOTER_LEN;
   
   DEBUG_TRACE("Found APEv%d tag, size %d with %d items\n", tag->version, tag->size, tag->item_count);
@@ -289,6 +289,10 @@
   unsigned char *tmp_ptr;
   SV *key = NULL;
   SV *value = NULL;
+
+  if (buffer_len(&tag->tag_data) < 8) {
+         return _ape_error(tag, "No more data to parse but specified number of items not found", -999999);
+  }
   
   size  = buffer_get_int_le(&tag->tag_data);
   flags = buffer_get_int_le(&tag->tag_data);


[not sure what the error numbering scheme is Andy - assume this needs a new error??]

Thanks. Did you mean to make the earlier change from FOOTER_LEN to HEADER_LEN? The error codes are a relic and don't matter.

Its moot as FOOTER_LEN and HEADER_LEN are the same, but I think the logic is such that it should be the header length.  The field read is the "Tag size in bytes including footer and all tag items excluding the header" according to:

http://wiki.hydrogenaudio.org/index.php?title=APE_Tags_Header

so the total size should be this + the header size.emacs

 == Auto-comment from SVN commit #872 to the opensource repo by agrundman ==
 == http://svn.slimdevices.com/opensource?view=revision&revision=872 ==

Fixed bug 15895, better handling if we have a broken APE tag and run out of tag data

Please test with 7.6.1 build 32962 or later.

I've tested with 7.6.1 build 32962 on Windows XP.
The fix resolved the problem and all my files are now scanned and added to the library (although there are still some strange effects, but not related to this bug).
Thanks for resolving this! You've made my day!
Best Regards, Jürgen