Bug 8727 - MusicIP import failing
: MusicIP import failing
Status: RESOLVED DUPLICATE of bug 8443
Product: Logitech Media Server
Classification: Unclassified
Component: MusicIP
: 7.1
: PC Windows XP
: P3 normal (vote)
: 7.x
Assigned To: Michael Herger
:
Depends on:
Blocks:
  Show dependency treegraph
 
Reported: 2008-07-14 11:08 UTC by Jordan Hirsch
Modified: 2009-07-31 10:24 UTC (History)
1 user (show)

See Also:
Category: ---


Attachments
Server & Scanner Logs (10.00 KB, application/x-zip-compressed)
2008-07-15 06:46 UTC, Jordan Hirsch
Details
Log file (61.48 KB, application/octet-stream)
2008-07-27 19:54 UTC, Jordan Hirsch
Details
Server and scanner logs from rescan (5.98 KB, application/x-zip-compressed)
2008-07-29 13:16 UTC, Jordan Hirsch
Details
Latest server & scanner logs + mmm-song-data.txt (4.39 MB, application/x-zip-compressed)
2008-08-17 08:33 UTC, Jordan Hirsch
Details
Server & scanner logs with correct debug information. (4.45 MB, application/x-zip-compressed)
2008-08-18 07:02 UTC, Jordan Hirsch
Details
Logs from clear & rescan (5.72 MB, application/x-zip-compressed)
2008-08-21 15:06 UTC, Jordan Hirsch
Details

Note You need to log in before you can comment on or make changes to this bug.
Description Jordan Hirsch 2008-07-14 11:08:26 UTC
I am using:

SqueezeCenter Version: 7.1 - 21263 @ Fri Jun 27 08:22:07 PDT 2008 - Windows XP - EN - cp1252

and

MusicIP Mixer Version: 1.9

I have the automatic rescan plugin enabled in SqueezeCenter and have it set to run every day at 4:00 AM (set to look for "New and Changed Music".  Prior to that, I have a job that runs on my computer and adds new files to my MusicIP library.  I can see the new files in the MusicIP library (both in the GUI and via the web interface), and I can make mixes off these new files (both in the GUI and via the web interface), but they do not show up as mixable in SqueezeCenter.

I have the MusicIP reload interval set to 0 since I don't want the rescan triggered automatically, I want to have it scheduled via the "Automatic Rescan" plugin.  However, as you can see from the results of a nightly rescan, MIP is not getting imported:

  Directory Scan   (3  of  3)   Complete  01:17:03
  Playlist Scan   (24  of  24)   Complete  00:01:50
  Merge Various Artists   (6262  of  6262)   Complete  00:01:53
  Database Cleanup #1   (60989  of  60989)   Complete  00:13:27
  Database Cleanup #2   Complete  00:01:08
  Database Optimize   Complete  00:03:17
  SqueezeCenter has finished scanning your music collection.  01:38:38

My directory is getting scanned properly, and music that used to be mixable via MIP is still mixable in SqueezeCenter, but recently added tracks (which are mixable via MusicIP directly) are not showing as mixable in SqueezeCenter.

When I set the MusicIP reload interval to a number higher than 0, a rescan was triggered immediately, and it did appear to import MusicIP data, but the newly added tracks were still not mixable.
Comment 1 KDF 2008-07-14 12:52:58 UTC
"new and changed" rescans will respect the rescan interval setting.  At 0 this means disabled.  Since this is nightly, and presumably, while sleeping try using the wipe and rescan option.
Comment 2 Jordan Hirsch 2008-07-14 15:41:21 UTC
Is this a change in 7?  In 6.5, when I had the rescan interval set to 0, the nightly "new & changed" still got all the MIP information - that's why I thought this was a bug.  Another question: are you recommending I do 1 clear & rescan, or that I have my nightly rescan always clear?

Thank you.
Comment 3 Michael Herger 2008-07-14 22:19:32 UTC
Don't know whether this has been changed. But would it work if you set the timeout to something linke 86400 (24h)?
Comment 4 Jordan Hirsch 2008-07-15 05:43:38 UTC
I did a clear & rescan last night (with the MIP reload interval set to 0), and here are the results:

Directory Scan   (60251  of  60251)   Complete  03:44:36
MusicIP Import   (1327  of  60124)   Running  04:24:21
\\readynas_nv\media\Music\MP3\The Mountain Goats\On Juhu Beach\01 Hotel Road.mp3
   (  of  )    
   (  of  )    
   (  of  )    
   (  of  )    
   (  of  )    
   (  of  )    
   (  of  )    
   (  of  )    
   (  of  )    
SqueezeCenter has finished scanning your music collection.08:08:57

All those empty parentheses above appeared as un-filled dots in the progress bar for MusicIP.  Squeezecenter reports that the scan is complete, but as you can see, only 1327 out of the 60124 MIP tracks got imported.  I still see many tracks in SqueezeCenter that are not mixable, but which are mixable via MusicIP GUI & web interface.

I haven't changed my reload interval yet as this appears to be an issue with the scanner itself - the MIP import is not finishing.
Comment 5 Michael Herger 2008-07-15 05:50:18 UTC
Please upload your server.log
Comment 6 Jordan Hirsch 2008-07-15 06:46:42 UTC
Created attachment 3588 [details]
Server & Scanner Logs
Comment 7 Jordan Hirsch 2008-07-15 06:47:07 UTC
Comment on attachment 3588 [details]
Server & Scanner Logs

Here are my server and scanner logs (I chose "1000 lines" for each).  I didn't have any extra debugging enabled during the clear & rescan, please let me know if you want me to run it again with any debug flags.

Thank you for your help.
Comment 8 Michael Herger 2008-07-16 08:16:25 UTC
From these logs I only see that MusicIP has gone away at some point. But that was in the afternoon, no message at night.

Please set logging for musicip to debug, too, then upload another copy of server.log. Thanks!
Comment 9 Jordan Hirsch 2008-07-16 12:29:52 UTC
(In reply to comment #8)
> From these logs I only see that MusicIP has gone away at some point. But that
> was in the afternoon, no message at night.
> 
> Please set logging for musicip to debug, too, then upload another copy of
> server.log. Thanks!
> 

Michael, just to be clear:  what steps do you want me to reproduce when I have musicip debugging turned on?  Should I keep the reload interval set to 0?  Should I do a full clear & rescan?  And is there any other debugging I should enable?

Thank you,
Jordan
Comment 10 Michael Herger 2008-07-21 02:38:42 UTC
Sorry for the delay. Yes, please run a re-scan (doesn't need to be wipe & rescan). Once this is running fine we'll have to take care of the nightly issue.

You seem to be using your music collection stored on a NAS/server. Could you please give me some more detail about your setup?
Comment 11 Michael Herger 2008-07-24 03:53:45 UTC
punting post 7.2
Comment 12 Jordan Hirsch 2008-07-27 08:20:36 UTC
Just got back into town from a long trip - I will run the scan and post my server log later on today or tomorrow.  By the way, it appears I'm not the only one having this issue:  http://forums.slimdevices.com/showthread.php?p=323233#post323233
Comment 13 Jordan Hirsch 2008-07-27 19:54:40 UTC
Created attachment 3690 [details]
Log file

This is the log file I generated by doing a scan ("new & changed") starting SqueezeCenter with these settings:

"c:\Program Files\SqueezeCenter\server\squeezecenter.exe" --d_musicmagic --d_scan --d_import --logfile=c:\slimserver.log --d_server --d_startup --d_cli
Comment 14 Jordan Hirsch 2008-07-27 19:56:26 UTC
Hello again,

I keep my music library on an Infrant ReadyNas NV device, but I am running SqueezeCenter off of my Windows XP PC.  I've had it set up this way since I first installed SlimServer 6.2 back in the day.  SlimServer/SqueezeCenter accesses the files via this type of path: \\Readynas_nv\media\music\... etc.

What else would be helpful for you to know?  Thank you.
Comment 15 Michael Herger 2008-07-28 01:55:44 UTC
"Scan Interval set to 0, rescanning disabled" - you seem to have disabled automatic scanning?
Comment 16 Jordan Hirsch 2008-07-28 06:22:20 UTC
(In reply to comment #15)
> "Scan Interval set to 0, rescanning disabled" - you seem to have disabled
> automatic scanning?
> 

My MusicIP reload interval is set to 0, as noted previously in the bug.  When I set it to anything higher, it just kicks off repeated rescans constantly, but they never succeed in importing all the MusicIP tracks.  Do you want me to set it to a higher interval and run the scan again?  (I had asked that previously but I thought you wanted me to leave it where it was).
Comment 17 Michael Herger 2008-07-28 08:13:54 UTC
The thread you've been refering to has a solution:
http://forums.slimdevices.com/showthread.php?p=323233#post323233#10 

Do you know that guy in the trenchcoat too? :-) You might also follow up on that thread, as this guy has an idea what was breaking his configuration.

We have to find out at which point and why the MusicIP seems to be aborted. We can take care of the nightly scans once you can do a full rescan.

> "c:\Program Files\SqueezeCenter\server\squeezecenter.exe" --d_musicmagic
> --d_scan --d_import --logfile=c:\slimserver.log --d_server --d_startup --d_cli

These parameters don't exist any more in SC7. Please set logging options in Settings/Advanced/Logging. Enable logging for MusicIP and the scan* options. Then run the rescan.

I just tested this on my local installation. The reload interval should be irrelevant.
Comment 18 Jordan Hirsch 2008-07-28 08:17:50 UTC
Michael,

Thank you for your continued help here - sorry for all the back and forth.  I had an old batch file I used to use when I needed to debug & log, but now I see those parameters are useless.  I will run the scan again with the debug options turned on that you indicated.  

I know that I do have some .cue files in my collection, but SS has always played them fine.  I don't know if I have any embedded cue files in my tags...not quite sure how to search the collection for those.  The import doesn't always seem to break on the same song consistently, so I don't know where to start looking.

But I'll scan again with the debug options you indicated and post my new log file.

Thank you again.
Comment 19 Jordan Hirsch 2008-07-29 13:16:58 UTC
Created attachment 3705 [details]
Server and scanner logs from rescan

Ran the rescan with all scan* and MusicIP logging options set to "debug."  Zip file contains server.log and 1000 lines of scanner.log.
Comment 20 John Keeling 2008-07-31 18:55:19 UTC
I just upgraded SC 7.0.1 to SC 7.1.0 (on Win XP SP3). MIP 1.9
MIP Plugin checked.
Basic Settings/ Music Folder is blank.
Advanced/MIP/Reload Interval set to 0

SC 7.1.0 initiated a "Clear and Rescan" of my library as part of the upgrade. It picked up all 29,000 tracks but did not find the playlists in MusicIP.
I restarted the computer, confirmed that I can create a MusicIP mix in SqueezeCenter (in other words the MusicIP plugin works) and then initiated a "rescan playlists only". Again the MusicIP playlists did not appear in SqueezeCentre.

SC 7.0.1 picked up the playlists in MusicIP and called them something like "MusicIP Playlist Playlist Name"

The workaround is to save the playlists in MIP using the "Save as playlist" function then do a "Rescan playlists only" in SC.

To recreate this, make a mix in MIP and name it, then do a "Rescan playlists only"
Comment 21 Jordan Hirsch 2008-08-01 07:56:28 UTC
(In reply to comment #20)
> SC 7.1.0 initiated a "Clear and Rescan" of my library as part of the upgrade.
> It picked up all 29,000 tracks but did not find the playlists in MusicIP.

John, I think you are describing a different issue than what's happening here - this bug described a problem importing tracks from MIP, not importing pre-existing playlists.
Comment 22 Jordan Hirsch 2008-08-01 07:57:17 UTC
(In reply to comment #20)
> SC 7.1.0 initiated a "Clear and Rescan" of my library as part of the upgrade.
> It picked up all 29,000 tracks but did not find the playlists in MusicIP.

John, I think you are describing a different issue than what's happening here - this bug described a problem importing tracks from MIP, not importing pre-existing playlists.
Comment 23 John Keeling 2008-08-01 13:53:19 UTC
Jordan,
I thought my problem was related to yours. Should I open a new bug?
I am going to my wife's house (400Km away) where I have another SB3 and computer system. I will upgrade it to SC7.1.0 and will see if the MIP mixes are imported.
I also emailed support, but due to time zone differences (Australia / West Coast USA) there is a overnight delay in response.
Comment 24 John Keeling 2008-08-02 18:39:47 UTC
Question : Should I open a new bug for this problem ?

I upgraded a second system (WinXP SP3) from SC 7.0.1 to SC 7.1.0 and once more playlists in MIP were not picked up by the scan process.
Comment 25 Jordan Hirsch 2008-08-02 20:11:10 UTC
(In reply to comment #24)
> Question : Should I open a new bug for this problem ?
> 
> I upgraded a second system (WinXP SP3) from SC 7.0.1 to SC 7.1.0 and once more
> playlists in MIP were not picked up by the scan process.
> 

Yes, I would say you should open a new bug.
Comment 26 John Keeling 2008-08-02 23:33:16 UTC
Jordan, I have created bug 9002 >>-> https://bugs-archive.lyrion.org/show_bug.cgi?id=9002
Please accept my apologies if you thought I was trying to hijack your bug, I did think it was further proof of scanning problems with MIP.
Comment 27 Jordan Hirsch 2008-08-06 11:44:47 UTC
(In reply to comment #17)
> These parameters don't exist any more in SC7. Please set logging options in
> Settings/Advanced/Logging. Enable logging for MusicIP and the scan* options.
> Then run the rescan.

Michael, were you able to glean any information from my latest log files?  Thank you.
Comment 28 Michael Herger 2008-08-06 23:53:31 UTC
I'm sorry, I haven't had time to take a closer look yet.
Comment 29 Michael Herger 2008-08-14 04:51:56 UTC
Jordan - from what I see in the logs your scan is shut down at some point due to some failure in the MusicIP scanner. Please enable debugging for plugin.musicip and launch a rescan. After it has stopped (very likely without finishing), please upload the scanner.log and a file called mmm-song-data.txt. You should find it in SC's cache folder (it's the data MusicIP is returning to SC). It might help us find the file and reason why the analysis is failing.
Comment 30 Jordan Hirsch 2008-08-17 08:32:36 UTC
(In reply to comment #29)
> Jordan - from what I see in the logs your scan is shut down at some point due
> to some failure in the MusicIP scanner. Please enable debugging for
> plugin.musicip and launch a rescan. After it has stopped (very likely without
> finishing), please upload the scanner.log and a file called mmm-song-data.txt.
> You should find it in SC's cache folder (it's the data MusicIP is returning to
> SC). It might help us find the file and reason why the analysis is failing.
> 

OK, I reran the scan with the MusicIP plugin and scan* logging options set to "debug."  I have also included mmm-song-data.txt in the zip file with the logs.

Here is what the web interface reported from the scan:

Directory Scan   (186  of  186)   Complete  00:46:01
MusicIP Import   (1325  of  60167)   Running  01:08:53
\\readynas_nv\media\Music\MP3\The Mountain Goats\On Juhu Beach\01 Hotel Road.mp3
   (  of  )    
   (  of  )    
   (  of  )    
   (  of  )    
   (  of  )    
   (  of  )    
   (  of  )    
   (  of  )    
   (  of  )    
SqueezeCenter has finished scanning your music collection. 01:54:54

Thank you again very much for your help with this.
Comment 31 Jordan Hirsch 2008-08-17 08:33:45 UTC
Created attachment 3817 [details]
Latest server & scanner logs + mmm-song-data.txt
Comment 32 Michael Herger 2008-08-18 04:40:41 UTC
Jordan - scanner.log is still missing the plugin.musicip debug data. This really would help a lot, as it lists all the tracks as they are imported. While trying to import your file SC failed at the same track over and over again. But then I don't have you music files. It would be better if we knew where it failed on your installation.

From your log file I guess the failure is at track 1328. According to mmm-song-data.txt this might be the following track:

\\readynas_nv\media\Music\Hi-Fi\Bud Powell\The Legacy\disc 2 - ...With Mingus\01 How High The Moon.flac

If it continues failing at this point, could you please move that folder outside your music collection and try again?
Comment 33 Jordan Hirsch 2008-08-18 04:56:40 UTC
(In reply to comment #32)
> Jordan - scanner.log is still missing the plugin.musicip debug data. This
> really would help a lot, as it lists all the tracks as they are imported. While

Michael,

I don't understand - I turned on musicip debug logging before running the scan (as I have the last couple times I posted my logs here).  Can you think of any reason the debug info isn't showing up in my log file?

I will try removing that song and seeing what happens.  And I would be happy to post another log with the right info, but I'm not sure how else to force it to include musicip debug information other than setting "(plugin.musicip) - MusicIP Mix & Export Logging" to "Debug" in the "Logging" area of the settings?

Thanks,
Jordan
Comment 34 Michael Herger 2008-08-18 05:08:25 UTC
That's odd. Try checking the "Save logging settings...", then restart SC and verify the log settings. Run the scan. Then disable the debugging again (checking the above again - to save the disabled state). 
Comment 35 Jordan Hirsch 2008-08-18 07:01:36 UTC
Michael,

I checked the "save logging settings" box, shut down SS, backed up and deleted server.log & scanner.log, restarted SS, reran the music scan, and verified that there is indeed much more information in the scanner & server logs than there was last time.

I also took a look at the song you identified in your last post - that whole album had its track numbers set to "-1."  I corrected that, but it did not appear to fix the problem; the scan still stops at the same place.  I have done a spot check for embedded cue files (since that seemed to be causing this issue for someone else) but haven't found any yet - I'm not entirely sure which songs I should be checking.

I will post the latest logs in a second, as well as the mmm-song-data.txt.

Thank you again for your help.
Comment 36 Jordan Hirsch 2008-08-18 07:02:37 UTC
Created attachment 3821 [details]
Server & scanner logs with correct debug information.
Comment 37 Jordan Hirsch 2008-08-18 07:47:19 UTC
I took a look through the logs and it looks like the last song it tried to import was "\\Readynas_nv\media\Music\Hi-Fi\The Watson Twins\Fire Songs\01 How Am I to Be.flac."

That song actually did have an embedded cuesheet!  (Are those supported by SqueezeCenter?)  I disabled the embedded cuesheet (for that file only, not for the other tracks in the album) so I can test and see if it will scan past that song now.  I'll post the scan results when it finishes.

If this is the problem, I believe this is a bug in the importer, no?  In the meantime, is there any way to search my library for all files that have an embedded cuesheet?
Comment 38 Michael Herger 2008-08-18 07:54:24 UTC
Cue sheets should be ok. But could you please verify it's values? Does the cue sheet have some title information?
Comment 39 Jordan Hirsch 2008-08-18 08:02:21 UTC
I rashly removed the cuesheet in question from that file before reading it closely, but here is the embedded cuesheet from Track 2 from the same album:

---------------------------------
REM DATE 2008
PERFORMER "Watson Twins"
TITLE "Fire Songs"
FILE "DUMMY" WAVE
  TRACK 01 AUDIO
    TITLE "Lady Love Me"
    ISRC USVG20802010
    INDEX 01 00:00:00
---------------------------------
Comment 40 Jordan Hirsch 2008-08-18 08:03:33 UTC
Sorry, I spoke too soon.  Even though I had unchecked "enable embedded cuesheet for this file" in foobar2000, it looks like Track 1 of that album still has an embedded cuesheet.  Here is its value:

-------------------------------
REM DATE 2008
PERFORMER "Watson Twins"
TITLE "Fire Songs"
FILE "DUMMY" WAVE
  TRACK 01 AUDIO
    TITLE "How Am I to Be"
    ISRC USVG20802009
    INDEX 01 00:00:00
-------------------------------
Comment 41 KDF 2008-08-18 09:30:54 UTC
crash is probably due to a bad $albumObj ($albumObj->title).  see ~line 2173-2185 of Schema.pm (rather than line 2016 which doesn't appear to have any code)
Comment 42 Jordan Hirsch 2008-08-18 11:33:25 UTC
(In reply to comment #41)
> crash is probably due to a bad $albumObj ($albumObj->title).  see ~line
> 2173-2185 of Schema.pm (rather than line 2016 which doesn't appear to have any
> code)

In my installation, C:\Program Files\SqueezeCenter\server\Slim\schema.pm does indeed have code on line 2016, here's lines 2004-2020:

-------------------------------------
# we may have an album object already..
# But mark it undef first - bug 3685
my $albumObj = undef;

if (!$create && $isLocal) {
	$albumObj = $track->album;

	# Bug: 4140
	# If the track is from a FLAC cue sheet, the original entry
	# will have a 'No Album' album. See if we have a real album name.
	my $noAlbum = string('NO_ALBUM');

	if ($album && $albumObj->title eq $noAlbum && $album ne $noAlbum) {

		$create = 1;
	}
}
-------------------------------------
Comment 43 Michael Herger 2008-08-21 10:14:08 UTC
Hmm... thought I had commented on this: I run into the "same" issue at home, MIP crashing at some point in the scan. A full wipe/rescan fixed it for me. Did you ever try this?
Comment 44 Jordan Hirsch 2008-08-21 13:55:45 UTC
(In reply to comment #43)
> Hmm... thought I had commented on this: I run into the "same" issue at home,
> MIP crashing at some point in the scan. A full wipe/rescan fixed it for me. Did
> you ever try this?

Yes, I tried that (see Comment #4 above) and got the same result.  I am trying it again today and expect I will get the same result - there's something wrong with the scanner code when it finds an embedded cue sheet in a FLAC file, apparently.
Comment 45 Jordan Hirsch 2008-08-21 15:06:29 UTC
Created attachment 3862 [details]
Logs from clear & rescan

These are the logs from doing a total clear & rescan.
Comment 46 Jordan Hirsch 2008-08-23 05:18:57 UTC
(In reply to comment #43)
As you can see in the latest log files, it crashes at exactly the same place during the MusicIP import section of the full wipe & rescan.
Comment 47 Jordan Hirsch 2008-08-24 07:13:28 UTC
I was just looking at the changelog for 7.2, and it mentions bug #4443, which seems like it might be the same problem.  I'm installing 7.2 now and will try a scan with it ASAP.
Comment 48 Jordan Hirsch 2008-08-24 19:00:31 UTC
Turns out this was a dup. of 4443 - I didn't think to search again once the problem had been identified; I thought this was a MusicIP problem, not a scanner problem.  Interestingly the song(s) in question import fine via directory scan, just not via MusicIP.  Either way, upgrading to 7.2 solved this issue for me.  Thank you.

*** This bug has been marked as a duplicate of bug 4443 ***
Comment 49 Jordan Hirsch 2008-08-24 19:01:49 UTC
Sorry, typo in previous comment - that's 8443, not 4443.

*** This bug has been marked as a duplicate of bug 8443 ***
Comment 50 Michael Herger 2008-08-24 22:55:15 UTC
thanks for following up on this issue!
Comment 51 Chris Owens 2009-07-31 10:24:47 UTC
Reduce number of active targets for SC