Jonathan: can you turn on logging and get the output from formats.playlist info and attach?

(In reply to comment #1)
> Jonathan: can you turn on logging and get the output from formats.playlist info
> and attach?
> 

Dean -- Apologies for the newbie question... How do I generate this output?

server settings->advanced->logging.
set formats.playlist to debugging and click "apply" button at the bottom.
You'll find the locations of the logs noted at the top of the page.  they will also link to the files so you can view in the browser.
trigger the playlist scan, then you can attach scanner.log to this report using the "create a new attachment" link in the top part of the bug page.

Created attachment 2663 [details]
Scanner log

Here is a copy of my scanner log. Note that the first playlist wound up being displayed in the "Playlists" section of the SC7 home page, the second did not. 

When I look in the tracks database, the first playlist appears as a track with content_type 'ssp' (these get displayed) and the second playlist (second in scanner.log) is listed with a content_type of 'm3u' and is NOT displayed as a playlist in SC7.

I can't seem to reproduce this one.

If you can still reproduce it, can you post another log and this time include scan.scanner as well as formats.playlists?

Created attachment 2710 [details]
Scanner log

I am able to reproduce this problem at will.

I have enclosed a scan log produced by scanning twice:

1. The first time I scanned new.m3u after restarting SC7. This playlist properly got placed in the tracks database with a content_type of 'ssp'.

2. I then made an exact copy of new.m3u and called in new2.m3u and scanned a second time. This playlist got saved in the tracks table with a content_type of 'm3u'.

It seems like the scan (or import into the database) works once after restarting the server. After that, any playlist I scan gets imported with the track type of 'm3u'.

Note that in both cases, the playlist tracks (in playlist_track) are always imported correctly.

So by going into the tracks database and changing the content_type of the second playlist to 'ssp' it (the playlist) gets displayed correctly in the Playlists section of the home screen.

Still cannot reproduce.  Here are the steps I took.

Delete all playlists in playlists folder.
Wipe and rescan library.
Add new.m3u to playlists folder.
Rescan playlists.
Check database, playlist has type ssp and works fine.
Copy new.m3u to new2.m3u.
Rescan playlists (only the new one is scanned)
Check database, playlist has type ssp and works fine.

I am going to assign to this QA to try to reproduce.

Those steps are the same I take and I can reproduce at will.

Thanks 

Jonathan

I just saw the following in scanner.pm:

	# With the special url if the playlist is in the
	# designated playlist folder. Otherwise, Dean wants
	# people to still be able to browse into playlists
	# from the Music Folder, but for those items not to
	# show up under Browse Playlists.
	#
	# Don't include the Shoutcast playlists or cuesheets
	# in our Browse Playlist view either.
	my $ct = Slim::Schema->contentType($playlist);

	if (Slim::Music::Info::isFileURL($url) && Slim::Utils::Misc::inPlaylistFolder($url)) {

		$ct = 'ssp';
	}

	$playlist->content_type($ct);
	$playlist->update;

What if the condition that sets content_type to 'ssp' is for some reason not being satisfied? I'm not set up to compile the server here but might I be able to get a copy with some heavy logging in this area? That way I could report back with findings.

Yeah I looked at that code too, but your playlists are in the playlist folder and are file URLs, so I don't think that is the problem.

If you install ActivePerl you can run slimserver.pl instead of .exe and then add your own logging if you want to debug further.

One other debug flag you could add is scan.import.

Theoretically it shouldn't be the problem but is there anywhere else in the code where content_type is set? If not, I then  this location looks key.

I will try the activeperl thing.

Simply running slimserver.pl with perl does not work -- it sounded a bit too easy.

I get the following error:

The following modules failed to load: DBD::mysql JSON::XS YAML::Syck GD

To download and compile them, please run: C:/svn-slim2/Bin/build-perl-modules.pl
 DBD::mysql JSON::XS YAML::Syck GD

Of course running this necessitates getting gzip, gnu c etc... a little more than I want in order to add some logging. Is there a way around this so that I can get slimerserver.pl running?

All the modules you need are included, you should not need to do anything except install ActivePerl.

Try: perl slimserver.pl --d_startup

Created attachment 2713 [details]
log file of problem when trying to start slimserver.pl

Here is the log file detailing the issues with starting slimserver.pl.

Am not sure if getting this working is more complicated than solving the original issue but I am willing to work through this with a little guidance.

Did you download ActivePerl 5.10?  Try the 5.8.8.822 release.

Created attachment 2720 [details]
Scanner log

Finally got slimserver.pl going. (Going back to ActivePerl 5.8 helped a lot)

I have attached a piece of scanner log with more detail in it. Sure enough, you can see in the log that by the time we get to Slim::Schema::updateOrCreate the content_type is somehow 'm3u'.

Let me know if I can help look for anything.

Andy: Does this log help?

Dean: This bug needs to be reproduced by QA as I can't reproduce it.

QA:  We need your help reproducing.

Ross: can you take a look at this?

So far I'm also unable to reproduce this. Jonathan would you mind attaching one of your playlists that SqueezeCenter consistently marks as content_type m3u?

Created attachment 2757 [details]
playlist

I don't believe the actual playlist file has anything to do with it as I am able to reproduce with hand-created m3u files, and others created by different programs. I am attaching one playlist in particular that I reproduced with.

Thanks - Jonathan

One additional note -- If I re-start SC7 then I believe the playlist I attached (or any playlist) will import with content_type set to 'ssp'. It is when I import (re-scan) the second, third etc time that each newly-added playlist is added with content_type m3u.

Thanks - Jonathan

Got it!

Hi guys -- I believe I've found the problem and can confirm with my "fix" the scanning for playlists always works.

Please bear with me as I'm really a C++ programmer so I'm a bit of a newbie when it comes to Perl. I will give line numbers but my line numbers may be a little off as I've added some extra log statements in the source files that I have.

As I understand it, when SC7 first adds a new playlist entry to the database, the new record in the tracks table always has a content_type of 'm3u'. (confirmed with scanner logs). Later in scanner.pm we have this code (around line 872):

	if (Slim::Music::Info::isFileURL($url) && Slim::Utils::Misc::inPlaylistFolder($url)) {
		$ct = 'ssp';
	}
	$playlist->content_type($ct);
	$playlist->update;

Here, the content_type is updated to 'ssp' based on the conditions in the 'if' statement. As expected, the condition is satisfied so the 'update' method gets called with a new content_type of 'ssp'.

The problem is in the update method in DBI.pm (around line 29):

sub update {
	my $self  = shift;

	if ($self->is_changed) {
		$dirtyCount++;
		$self->SUPER::update;
        }

	# This is only applicable to the scanner, as the main process is in AutoCommit mode.
	# Commit to the DB every 500 updates.. just a random number.
	if (($dirtyCount % 500) == 0) {

		Slim::Schema->forceCommit;
		$dirtyCount = 0;
	}

	return 1;
}


In my case the is_changed check is true but a commit doesn't really occur there. I guess a commit is set to happen only when dirtycount == 500. This apparently doesn't always happen. When I force a commit... ie:

	if ($self->is_changed) {
		$dirtyCount++;
		$self->SUPER::update;
                Slim::Schema->forceCommit;
		$dirtyCount = 0;
        }

then my import always works.

So I guess if the dirty flag is hit 500 times, things will work... I still can't explain why this is hard to reproduce and why I'm the only one to see this behaviour.

Does this help?

Thanks,

Jonathan

Thanks for debugging it some more.  Hmm, forceCommit should always be run at the end of the scan process so it should still commit the changes.

Andy -- where is that final forcecommit in the source? I can perhaps put more logging there to see what's going on.

Wow thanks Jonathan! Please let me know if you need anything from QA. 

Andy: is this a 7.0 bug?

Not sure Dean.  Sorry Jonathan, check all the forceCommit calls in Slim::Schema.

Created attachment 2805 [details]
scanner logs

I've created two new logs -- scanner-1.log is run immediately after re-starting the server. It displays many references to forcecommit. Scanner-2.log is created by scanning a second time. Both show that SC7 finds and reads playlists in similar ways.

Notably, scanner-2.log shows NO reference to forcecommit.

Jonathan

Are you sure you listed them in the right order?  scanner-2 has the many reference to forceCommit while scanner-1 only shows 2 at the very beginning of the log.

Were both scans run the same way?  Was this a 'clear and rescan everything' scan?  How come you didn't just run a 'rescan playlists'?  I thought you were having the problem with just a playlist rescan.

Still no luck reproducing, I've added some additional debugging lines in change 17132 to indicate when a playlist content-type changes to ssp and when forceCommit is not run due to AutoCommit mode being enabled.

You are right -- based just on the timestamps in each scan log, I listed them in the wrong order.

Both scans (and any scan I've done for this isssue) were run precisely the same way. I ran a RESCAN PLAYLISTS. I did not run a rescan everything and yes, my problem is with scanning playlists.

Created attachment 2807 [details]
scanner log

I ran with the newer versions of schema.pm and scanner.pm.

I've attached the log and it has no mention of the new 'autocommit' log entries. (It is also not showing lines that indicate a forcecommit except at the very beginning of the scan)

OK, that log only shows one playlist and it is scanned fine and was set to ssp.  I do not know why you are not seeing forceCommit log entries.

It looks like you cut off the log before the scan finished, that may be why you don't see a commit in there.

I added a forceCommit to the endImporter method, will commit after each scanning phase.  Not sure if it will help with this problem, but it can't hurt.

>> OK, that log only shows one playlist and it is scanned fine and was set to ssp.
>> I do not know why you are not seeing forceCommit log entries.

This has been the issue from the very beginning. I have noted several times above that the code is changing the content_type to 'ssp' but this is never committed to the database (unless we are scanning for the first time after re-starting the server).

I am not seeing the forcecommit log entries because for some reason forcecommit is not being called. If I add lines to call it (as noted above), then forcecommit appears in the log.

> It looks like you cut off the log before the scan finished, that may be why you don't see a commit in there.

No, I didn't cut the log off -- that is all that is there. Every log I have submitted in the last couple of days (even ones where forcecommit appears) end in precisely the same place.

Hmm, so the real problem may be that the scanner is not finishing for some reason.  Anyway, try change 17137 and see if that fixes the problem.

> Hmm, so the real problem may be that the scanner is not finishing for some
> reason.  Anyway, try change 17137 and see if that fixes the problem.

That did it -- the playlist appears so the added commit works.

I think you're right -- it looks like in my case, the scan never really finishes. It always cuts off on the same mp3 when performing the artwork scan.

Do you want me to open a new bug for this? Do you want me to submit the mp3 in question?

BTW, when is the next build -- I'd like to back to running a compiled slimserver :-)

Thanks,

Jonathan

Great.  If it's always failing on the same mp3, please attach it to a new bug.  There will be another build tonight.  I'm marking this bug fixed.

This bug is being closed since it was resolved for a version which is now released!  Please download the new version of SqueezeCenter (formerly SlimServer) at http://www.slimdevices.com/su_downloads.html

If you are still seeing this bug, please re-open it and we will consider it for a future release.