Bug 9326 - Total Playing Time a negative number
: Total Playing Time a negative number
Status: RESOLVED WORKSFORME
Product: Logitech Media Server
Classification: Unclassified
Component: Web Interface
: 7.2
: Macintosh MacOS X 10.4
: P3 minor (vote)
: ---
Assigned To: Unassigned bug - please assign me!
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2008-08-28 20:25 UTC by Mark F. Ward
Modified: 2011-01-24 05:17 UTC (History)
5 users (show)

See Also:
Category: Task


Attachments
Screencap of the problem. (9.92 KB, image/png)
2008-09-19 16:25 UTC, Mark F. Ward
Details
Collected logs as requested (6.08 MB, application/zip)
2008-09-21 00:12 UTC, Mark F. Ward
Details
ScannerLog (196.55 MB, application/octet-stream)
2008-09-22 13:54 UTC, James Richardson
Details
ServerLog (3.13 MB, application/octet-stream)
2008-09-22 13:55 UTC, James Richardson
Details
More logs (8.28 KB, application/zip)
2008-09-25 22:50 UTC, Mark F. Ward
Details
Extracted Scanner log (173.25 KB, application/octet-stream)
2008-09-26 07:11 UTC, James Richardson
Details
Additional logs from rescan (38.72 KB, application/zip)
2008-09-26 09:27 UTC, Mark F. Ward
Details
scanner.log from a clear and rescan. (170.31 KB, application/octet-stream)
2008-09-29 19:51 UTC, Mark F. Ward
Details
Imagine album (210.60 MB, application/octet-stream)
2008-09-30 12:25 UTC, Mark F. Ward
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Mark F. Ward 2008-08-28 20:25:17 UTC
I have a rather large music library (in excess of 150k tracks). The Total Playing Time in Library Statistics displays as a negative number (currently "Total Playing Time: -1:44:30"). This bug has existed for many versions of the Squeezecenter software, to include those that predate Logitech etc.

SqueezeCenter Version: 7.2 - 22900 @ Tue Aug 26 11:08:53 PDT 2008 - Mac OS X 10.4.11 (8S2167) - EN - utf8
Perl Version: 5.8.6 darwin-thread-multi-2level
MySQL Version: 5.0.22-standard
Platform Architecture: x86

Steps to reproduce: Have a large library & import the whole thing into Squeezecenter.
Comment 1 James Richardson 2008-09-19 15:38:46 UTC
Please retest with 7.2.1 and attach a screen shoot of the error.  While I don't have quite as many tracks in my album, I don't see the negative number in my setup.

I only have about ~100k tracks
Comment 2 Mark F. Ward 2008-09-19 16:25:46 UTC
Created attachment 4034 [details]
Screencap of the problem.

This is a screencap of the problem, taken while using the latest stable release of SqueezeCenter.
Comment 3 Mark F. Ward 2008-09-19 16:28:56 UTC
(In reply to comment #2)
> Created an attachment (id=4034) [details]
> Screencap of the problem.
> 
> This is a screencap of the problem, taken while using the latest stable release
> of SqueezeCenter.
> 

I am installing the nightly build of 7.2.1 and will resubmit a screencap after the update.
Comment 4 Mark F. Ward 2008-09-19 17:47:29 UTC
Problem is reproduced under version:

SqueezeCenter Version: 7.2.1 - 23219 @ Fri Sep 19 02:02:39 PDT 2008 - Mac OS X 10.4.11 (8S2167) - EN - utf8

No need for another screencap as it's exactly the same as before. I rescanned my library (using the look for new and changed music option) before checking to see if the problem persisted.
Comment 5 James Richardson 2008-09-20 15:40:58 UTC
While it may take awhile to complete, can I ask that you do a clear and rescan as well?

Please set the following LOGGING options to DEBUG first, then attach the log to this bug if you still see the negative numbers:

SC > Settings > Advanced > Logging:

(scan) - All Scan Logging

(scan.import) - File & Playlist Metadata Import Logging

(scan.scanner) - Music & Playlist Folder Scanning 
Comment 6 Mark F. Ward 2008-09-21 00:12:01 UTC
Created attachment 4039 [details]
Collected logs as requested
Comment 7 Mark F. Ward 2008-09-21 00:13:20 UTC
Problem persisted after rescan from scratch. Note that the rescan took two tries - this is not uncommon. I suppose I should submit it as another bug, but hey let's get this one done first.
Comment 8 James Richardson 2008-09-22 13:54:20 UTC
Created attachment 4042 [details]
ScannerLog

Looking at this log, I see LOTS of errors.
Comment 9 James Richardson 2008-09-22 13:55:01 UTC
Created attachment 4043 [details]
ServerLog
Comment 10 James Richardson 2008-09-23 09:17:31 UTC
Using 10.5.5 I was still unable to reproduce this issue.  My library is now 188,209 Tracks. 11,847 Albums. Total Playtime 4477:03:42.

Michale/Andy: can you see anything wrong in his logs? or anything in the WEB UI that would cause this issue?
Comment 11 Michael Herger 2008-09-23 23:11:13 UTC
Mark - do you see the same odd numbers in the player interface?

James - can you test on OSX?
Comment 12 James Richardson 2008-09-24 08:16:41 UTC
(In reply to comment #11)
> Mark - do you see the same odd numbers in the player interface?
> 
> James - can you test on OSX?
> 

I tested OSX 10.5.5
Today I will be testing with OSX 10.4.x
Comment 13 Spies Steven 2008-09-24 13:35:30 UTC
Mark, I was also wondering if you have tried just adding a portion of your library to SqueezeCenter and then doing clear and rescan library.  Do you still get the incorrect play time?

I was also curious if you have tried a completely clean install of SqueezeCenter.

In order to do this would require the removal of the following files:
- Home > Library > Application Support > SqueezeCenter Folder
- Home > Library > Caches > SqueezeCenter folder
- Home > Library > Logs > SqueezeCenter folder
- Home > Library > PreferencePanes > SqueezeCenter.prefPane
- Home > Library > Preferences > com.slimdevices.slim.plist
- Macintosh HD > Library > PreferencePanes > SqueezeCenter.prefPane (may or may not exist) 

I also suggest renaming the following as a backup if you have saved playlists otherwise it should be removed as well:
- Home > Music > Playlists

Once these files have been removed SqueezeCenter can be installed cleanly.
Comment 14 Mark F. Ward 2008-09-24 18:46:01 UTC
(In reply to comment #13)
> Mark, I was also wondering if you have tried just adding a portion of your
> library to SqueezeCenter and then doing clear and rescan library.  Do you still
> get the incorrect play time?

Well, I generally have to scan at least twice to get a clear and rescan to get all my albums. The first scan consistently terminates early, so then I have to do a 'check for new music' scan. I haven't checked to see if the play time looks funny after the first scan -- I'll take a look.

> I was also curious if you have tried a completely clean install of
> SqueezeCenter.

Trying that now with the 7.2.1 nightly build.

As an aside, I'm a big fan of your products and have been using them for years. At my last startup we had a few Squeezeboxes around the office and music was a constant companion. Now I'm consulting so it's headphones time :-\ -- at least until I get home!

Cheers,

mfw
Comment 15 Mark F. Ward 2008-09-24 19:39:51 UTC
Update: I installed from scratch. The initial scan terminated early, though the counter on the Status page continues to tick away. The playing time looks okay (i.e. it's a positive integer). I will kick off a clean rescan and report back in. If it doesn't finish (they generally do not), then I will kick off a new & changed music rescan.
Comment 16 Spies Steven 2008-09-25 09:00:12 UTC
(In reply to comment #15)
> Update: I installed from scratch. The initial scan terminated early, though the
> counter on the Status page continues to tick away. The playing time looks okay
> (i.e. it's a positive integer). I will kick off a clean rescan and report back
> in. If it doesn't finish (they generally do not), then I will kick off a new &
> changed music rescan.

Terminated early? We might be getting somewhere.  It sounds like the scanner is hanging or crashing on a particular file.  The key is to get a good log of this event.  I suggest doing a clean install once more and when you walk through the wizard uncheck all the music sources.  This will allow you to get through the wizard without a scan starting.  Once the wizard finishes go turn on the logging options James mentions in comment #5.  Now add your music sources under basic settings and or enable iTunes and MusicIP.  Once applied a scan should start.  When the scan crashes of freezes please attach the scan log to this bug.

Thanks for taking the time to help diagnose this issue.
Comment 17 Mark F. Ward 2008-09-25 21:43:53 UTC
I'm doing another clean install and will attach the logs when the scan is done.

Thanks for helping to diagnose the problem is nothing - hey, I've worked at a bunch of places where even internally located bugs sat in bugzilla forever and ever. Good on you guys for squashing the pesky little buggers.

mfw
Comment 18 Mark F. Ward 2008-09-25 22:50:46 UTC
Created attachment 4065 [details]
More logs
Comment 19 James Richardson 2008-09-26 07:11:14 UTC
Created attachment 4071 [details]
Extracted Scanner log

Wow, there are lots of errors in this log...  Did you have your external source attached at the time you did the scan?

I see lots of
-------------
[08-09-25 22:04:23.8262] Slim::Formats::Playlists::CUE::parse (167) Error: Couldn't find referenced FILE: [/Volumes/Dalek/1-M/AK1200/Mixed Live/Ak1200 - Mixed Live.mp3] on disk! Skipping!
-------------
as well as
-------------
[08-09-25 22:14:03.9489] MP3::Info::_grab_int_16 (2143) Warning: substr outside of string at /Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/lib/MP3/Info.pm line 2143, <$fh> line 1.
[08-09-25 22:14:03.9491] MP3::Info::_parse_v2tag (721) Warning: Use of uninitialized value in substr at /Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/lib/MP3/Info.pm line 721, <$fh> line 1.
[08-09-25 22:14:03.9493] MP3::Info::_parse_v2tag (721) Warning: Use of uninitialized value in substr at /Library/PreferencePanes/SqueezeCenter.prefPane/Contents/server/lib/MP3/Info.pm line 721, <$fh> line 1.
-------------
Comment 20 Mark F. Ward 2008-09-26 09:27:50 UTC
Created attachment 4072 [details]
Additional logs from rescan

Logs from rescan after first clean scan failed.
Comment 21 Mark F. Ward 2008-09-26 09:33:30 UTC
(In reply to comment #19)
> Created an attachment (id=4071) [details]
> Extracted Scanner log
> 
> Wow, there are lots of errors in this log...  Did you have your external source
> attached at the time you did the scan?

I did a clean install, enabled no music sources, and let the server come up. Somehow it detected 6 or 7 mp3s - I have no idea how. I did not provide any music sources or enable iTunes. I then fired off a clean and scan - it terminated around 4400 albums in IIRC, which is typical. I fired off those logs to you, did a "look for new music" scan, and then just attached those logs.

I used the latest daily build, and yes my play time is a negative number.

The .cue parsing bugs are normal - those are poorly written .cue's I got from my DJ friends that are averse to splitting albums into individual tracks. If I edit the .cue to match the file name I am be good to go, an ongoing chore... The other errors are unknown to me.
Comment 22 KDF 2008-09-26 10:51:27 UTC
last attached log shows that the scan errors out during the playlist scan (seems that something is causing the scan to seek beyond and end of file).

try setting formats.playlists to DEBUG and it should tell you the url of the playlist that is causing the scan failure.
Comment 23 Mark F. Ward 2008-09-29 19:50:35 UTC
Update: I'm enclosing the debug log for the scanner. It seems to consistently die at 4451 albums with 52574 songs by 1549 artists. The log entries are not consistent (I did a few runs and looked at the diffs - the number of errors and which files it complains about are slightly different). However, every time the web UI stops on /Music/1-M/John Lennon/Imagine/Imagine.flac. Note that my music lives on two drives that are symlinked in a directory on the main drive, /Music.
Comment 24 Mark F. Ward 2008-09-29 19:51:15 UTC
Created attachment 4081 [details]
scanner.log from a clear and rescan.
Comment 25 James Richardson 2008-09-30 09:42:12 UTC
(In reply to comment #23)
> Update: I'm enclosing the debug log for the scanner. It seems to consistently
> die at 4451 albums with 52574 songs by 1549 artists. The log entries are not
> consistent (I did a few runs and looked at the diffs - the number of errors and
> which files it complains about are slightly different). However, every time the
> web UI stops on /Music/1-M/John Lennon/Imagine/Imagine.flac. Note that my music
> lives on two drives that are symlinked in a directory on the main drive,
> /Music.
> 

Can you attach that .flac file to the bug so we can investigate
Comment 26 Mark F. Ward 2008-09-30 12:25:55 UTC
Created attachment 4082 [details]
Imagine album

Here's the Imagine album that the scan seems to stall on.
Comment 27 Andy Grundman 2008-10-01 08:39:14 UTC
Works for me, that FLAC with cue is parsed fine in 7.2.1.
Comment 28 James Richardson 2008-10-02 10:01:12 UTC
Mark:

I'm out of ideas to try here.  I think the key is hidden somewhere in your files, but can't figure it out.

If you are willing, please try the following experiment to see if we can figure out where/when the issue happens.

1) Scan just a portion of your lib.  Lets try small to medium sub-sets of your library.  Please have SC do a 'clean' scan on sections of your music.  when the scanner halts, save the log, and try a different sub-set.

2) Scan music on the same HDD that your SC is installed to.  Lets try a portion of your library moved to the local drive where SC is installed to.

3) NO CUE files.  Lets try a sub-set of your library with no 'cue' style files.  Just MP3/FLAC/AAC type files

4) no PlayLists.  Try a sub-set scan with no Playlists enabled.

Unless some one else has other options, I don't know what else to suggest.
Comment 29 Chris Owens 2008-10-02 13:52:57 UTC
Since we haven't yet reproduced this in-house I'm moving it to 7.3
Comment 30 James Richardson 2008-10-17 15:52:09 UTC
Mark: have you had any progress on this issue?
Comment 31 Mark F. Ward 2008-10-17 16:46:23 UTC
(In reply to comment #30)
> Mark: have you had any progress on this issue?
> 

No, scans from scratch continue to die at roughly the same place. I have tried yanking the John Lennon 'Imagine' album and rescanning. Funny that album tanks the scan but anything by Slayer is fine... If it works I'll let y'all know, otherwise things continue as they were.
Comment 32 James Richardson 2008-11-10 16:25:07 UTC
We should retest this with 8.0 when the DB engine changes.
Comment 33 James Richardson 2009-05-21 09:06:49 UTC
Mark: Can I ask you to try a beta version of SC 7.4, let me know if this has any issues with your files.

You can download 7.4 from here: http://downloads.slimdevices.com/nightly/?ver=7.4

Please let us know how that vesion works for you.  After you have tested this version, you can either stay with it, or revert back to 7.3.2(3)
Comment 34 Pat Ransil 2009-07-30 16:15:16 UTC
Moving this to 8.0.1 since we have not reproduced in house. We will keep working on it but it won't be a blocker for the 7.4 release
Comment 35 James Richardson 2009-08-01 11:43:22 UTC
Adding time worked info, changing target to 8.0.1
Comment 36 James Richardson 2009-10-06 15:56:10 UTC
Mark: have you had a chance to test out 7.4.0 yet?  I have still not been able to replicate this issue, even with the tracks you provided.