Problems with "Play Next" in 7.2?

[GeeJay]

I've noticed a problem when trying to add a song using the PlayNext feature.

I've been using a random SQLPlaylist that I've had for some time. When I try to add a song by pressing and holding the "+" key, the song appears next on the Controller, as you would expect. The currently playing song continues, but stops just short of the end (about at the point crossfade would begin...but that's just a guess) and proceeds with the next track after the one I had tried to add.

Anyone experiencing anything similar? This feature was working fine for me a few weeks ago.

[MeSue]

I experimented some with this last night and didn't have any problems.

[GeeJay]

When I have more time (probably this weekend) I'll play around with this and see if I can replicate the problem under a number of different scenarios (e.g., using the remote vs. the Controller, although in the latter case I'm using it to control one of my SB3s, so I'm not sure how that would be different). I'll report back and post any error logs and see if I can get some of the smarter folks around here to help me figure it out. As I thought a bit more about this, I'm not entirely certain this started with my conversion to 7.2, although the feature worked for awhile at least after I converted to 7.1.

Sounds like this is a "one off" problem, which I thought might be the case since a search of the forums didn't yield any similar complaints.

[GeeJay]

It took me awhile to get back to this, but the problem continues. It happens whenever I have a random mix using SQL Playlist and Custom Skip. When I try to add a song to the playlist ("play next") it shows up on the playlist, and attempts to play, but after a split second it goes to the next tune in the mix. Here is a excerpt from the log file:

[08-10-18 16:25:32.6369] Plugins::SQLPlayList::Plugin::executeSQLForPlaylis t (854) Executing and collecting: select tracks.url from tracks left join dynamicplaylist_history on tracks.id=dynamicplaylist_history.id where audio=1 and dynamicplaylist_history.id is null and not exists (select * from tracks t2,genre_track,genres where t2.id=tracks.id and tracks.id=genre_track.track and genre_track.genre=genres.id and genres.name in ('Christmas','Holiday')) order by rand() limit 10;
[08-10-18 16:26:36.0743] Plugins::SQLPlayList::Plugin::executeSQLForPlaylis t (854) Executing and collecting: select tracks.url from tracks left join dynamicplaylist_history on tracks.id=dynamicplaylist_history.id where audio=1 and dynamicplaylist_history.id is null and not exists (select * from tracks t2,genre_track,genres where t2.id=tracks.id and tracks.id=genre_track.track and genre_track.genre=genres.id and genres.name in ('Christmas','Holiday')) order by rand() limit 10;
[08-10-18 16:31:15.2462] Plugins::SQLPlayList::Plugin::executeSQLForPlaylis t (854) Executing and collecting: select tracks.url from tracks left join dynamicplaylist_history on tracks.id=dynamicplaylist_history.id where audio=1 and dynamicplaylist_history.id is null and not exists (select * from tracks t2,genre_track,genres where t2.id=tracks.id and tracks.id=genre_track.track and genre_track.genre=genres.id and genres.name in ('Christmas','Holiday')) order by rand() limit 10;
[08-10-18 16:33:22.8662] Slim::Control::Commands:laylistcontrolCommand (1630) Begin Function
[08-10-18 16:37:38.5179] Slim::Control::Commands:laylistcontrolCommand (1630) Begin Function

The last two entries are when I attempted to add the songs. No errors. I changed the logging settings to include all error messages on SQL Playlist and Custom Skip.

This error occurs both when I use the Duet Controller and SoftSqueeze, so I don't think it's Duet related.

Any thoughts about what may be causing this?

[GeeJay]

I got out of the SQL Playlist and went with the standard Random Mix. Add Next worked fine. Maybe a problem with the plug in?

[GeeJay]

I upgraded to 7.2.1, but still have the problem. It seems to be isolated to SQLPlaylist, since I used the standard Random Mix and was able to add a track as expected.

I've set all of Erland's plug-ins to "debug" in the log file. I've extracted part of that file here. The playlist populates, and the first track (The Beatle's "She's A Woman") starts playing. I try to add Alexa Wilkinson's "Lions" as the next track, and indeed that track shows up next on the playlist when I press and hold the "+" button. But, as has been the case every other time I've tried this recently, the track is skipped and SC goes to the next song on the playlist. Here's the exerpt from the log file:

[08-11-04 20:51:30.8485] Plugins::TrackStat::Storage::findTrack (495) findTrack(): URL: file:///Z:/My%20Personal%20Music/The%20Rolling%20Stones/(Single)/The%20Rolling%20Stones%20-%20(Single)%20-%2001%20-%20Honky%20Tonk%20Women.mp3
[08-11-04 20:51:30.8509] Plugins::TrackStat::Plugin::getRatingDynamicCustom Item (4526) Exiting getRatingDynamicCustomItem
[08-11-04 20:53:08.8231] Plugins::TrackStat::Plugin::commandCallback65 (3662) Entering commandCallback65
[08-11-04 20:53:08.8237] Plugins::TrackStat::Plugin::stopTimingSong (3865) Stopping timing file:///Z:/My%20Personal%20Music/The%20Beatles/(Single)/The%20Beatles%20-%20(Single)%20-%2002%20-%20She%27s%20A%20Woman.mp3
[08-11-04 20:53:08.8241] Plugins::TrackStat::Plugin::stopTimingSong (3866) Total elapsed time in seconds: 161.831285
[08-11-04 20:53:08.8245] Plugins::TrackStat::Plugin::trackWasPlayedEnoughTo CountAsAListen (4060) Time actually played in track: 161.831285
[08-11-04 20:53:08.8248] Plugins::TrackStat::Plugin::trackWasPlayedEnoughTo CountAsAListen (4078) "She's A Woman" was played long enough to count as played.
[08-11-04 20:53:08.8251] Plugins::TrackStat::Plugin::trackWasPlayedEnoughTo CountAsAListen (4079) Played past percentage threshold of 91.5 seconds.
[08-11-04 20:53:08.8255] Plugins::TrackStat::Plugin::markedAsPlayed (3959) Entering markedAsPlayed
[08-11-04 20:53:08.8268] Plugins::TrackStat::Storage::findTrack (495) findTrack(): URL: file:///Z:/My%20Personal%20Music/The%20Beatles/(Single)/The%20Beatles%20-%20(Single)%20-%2002%20-%20She%27s%20A%20Woman.mp3
[08-11-04 20:53:08.8319] Plugins::TrackStat::Storage::findTrack (495) findTrack(): URL: file:///Z:/My%20Personal%20Music/The%20Beatles/(Single)/The%20Beatles%20-%20(Single)%20-%2002%20-%20She%27s%20A%20Woman.mp3
[08-11-04 20:53:08.8338] Plugins::TrackStat::Storage::savePlayCountAndLastP layed (705) Marking as played in storage
[08-11-04 20:53:08.8359] Plugins::TrackStat::Storage::addToHistory (762) Entering addToHistory
[08-11-04 20:53:08.8624] Plugins::TrackStat::Storage::addToHistory (867) Exiting addToHistory
[08-11-04 20:53:08.8629] Plugins::TrackStat::Plugin::markedAsPlayed (4000) Calling Plugins::TrackStat::Plugin
[08-11-04 20:53:08.8632] Plugins::TrackStat::Plugin::setTrackStatStatistic (4467) Entering setTrackStatStatistic
[08-11-04 20:53:08.8791] Plugins::TrackStat::Plugin::setTrackStatStatistic (4480) Exiting setTrackStatStatistic
[08-11-04 20:53:08.8798] Plugins::TrackStat::Plugin::markedAsPlayed (4008) Exiting markedAsPlayed
[08-11-04 20:53:08.8803] Plugins::TrackStat::Storage::findTrack (471) Reading slimserver track: file:///Z:/My%20Personal%20Music/The%20Beatles/(Single)/The%20Beatles%20-%20(Single)%20-%2002%20-%20She%27s%20A%20Woman.mp3
[08-11-04 20:53:08.8814] Plugins::TrackStat::Storage::findTrack (495) findTrack(): URL: file:///Z:/My%20Personal%20Music/The%20Beatles/(Single)/The%20Beatles%20-%20(Single)%20-%2002%20-%20She%27s%20A%20Woman.mp3
[08-11-04 20:53:08.8831] Plugins::TrackStat::Plugin::stopTimingSong (3935) Do not adjust rating, only played 161.831285 of required 173.85 seconds
[08-11-04 20:53:08.8835] Plugins::TrackStat::Plugin::startTimingNewSong (3757) Starting a new song
[08-11-04 20:53:08.8988] Plugins::TrackStat::Plugin::startTimingNewSong (3799) Starting to time file:///Z:/My%20Personal%20Music/Alexa%20Wilkinson/Lions/02%20-%20Lions.mp3
[08-11-04 20:53:08.8993] Plugins::TrackStat::Plugin::commandCallback65 (3747) Exiting commandCallback65
[08-11-04 20:53:28.9754] Plugins::TrackStat::Plugin::commandCallback65 (3662) Entering commandCallback65
[08-11-04 20:53:28.9771] Plugins::TrackStat::Plugin::commandCallback65 (3747) Exiting commandCallback65
[08-11-04 20:53:28.9778] Plugins:ynamicPlayList::Plugin::commandCallback65 (1631) received command playlist newsong
[08-11-04 20:53:28.9783] Plugins:ynamicPlayList::Plugin::commandCallback65 (1641) while in mode: sqlplaylist_randomtracks, from Soft Squeeze
[08-11-04 20:53:28.9789] Plugins:ynamicPlayList::Plugin::commandCallback65 (1671) Adding new tracks in 60 seconds
[08-11-04 20:53:28.9797] Plugins::CustomSkip::Plugin::newSongCallback (1960) Received newsong for file:///Z:/My%20Personal%20Music/Alexa%20Wilkinson/Lions/02%20-%20Lions.mp3
[08-11-04 20:53:28.9831] Plugins::CustomSkip::Plugin::executeDynamicPlayLis tFilter (577) Using secondary filter: Faves and Unrated
[08-11-04 20:53:28.9841] Plugins::CustomSkip::Plugin::executeDynamicPlayLis tFilter (599) Calling: Plugins::TrackStat::Plugin for trackstat_rated with: file:///Z:/My%20Personal%20Music/Alexa%20Wilkinson/Lions/02%20-%20Lions.mp3
[08-11-04 20:53:28.9846] Plugins::CustomSkip::Plugin::executeDynamicPlayLis tFilter (601) Calling: Plugins::TrackStat::Plugin :: checkCustomSkipFilterType
[08-11-04 20:53:28.9854] Plugins::TrackStat::Storage::findTrack (495) findTrack(): URL: file:///Z:/My%20Personal%20Music/Alexa%20Wilkinson/Lions/02%20-%20Lions.mp3
[08-11-04 20:53:28.9876] Plugins::CustomSkip::Plugin::executeDynamicPlayLis tFilter (608) Filter trackstat_rated matched
[08-11-04 20:53:28.9882] Plugins::CustomSkip::Plugin::executeDynamicPlayLis tFilter (616) Use skip percentage 100%
[08-11-04 20:53:28.9889] Plugins::CustomSkip::Plugin::executeDynamicPlayLis tFilter (644) Skip track: Lions
[08-11-04 20:53:29.0631] Plugins::CustomSkip::Plugin::newSongCallback (1986) Removing song from client playlist
[08-11-04 20:53:29.0680] Plugins::TrackStat::Plugin::commandCallback65 (3662) Entering commandCallback65
[08-11-04 20:53:29.0688] Plugins::TrackStat::Plugin::commandCallback65 (3747) Exiting commandCallback65
[08-11-04 20:53:29.0695] Plugins:ynamicPlayList::Plugin::commandCallback65 (1631) received command playlist deleteitem
[08-11-04 20:53:29.0701] Plugins:ynamicPlayList::Plugin::commandCallback65 (1641) while in mode: sqlplaylist_randomtracks, from Soft Squeeze
[08-11-04 20:53:29.0877] Plugins::TrackStat::Plugin::commandCallback65 (3662) Entering commandCallback65
[08-11-04 20:53:29.0885] Plugins::TrackStat::Plugin::stopTimingSong (3865) Stopping timing file:///Z:/My%20Personal%20Music/Alexa%20Wilkinson/Lions/02%20-%20Lions.mp3
[08-11-04 20:53:29.0890] Plugins::TrackStat::Plugin::stopTimingSong (3866) Total elapsed time in seconds: 20.189719
[08-11-04 20:53:29.0895] Plugins::TrackStat::Plugin::trackWasPlayedEnoughTo CountAsAListen (4060) Time actually played in track: 20.189719
[08-11-04 20:53:29.0900] Plugins::TrackStat::Plugin::trackWasPlayedEnoughTo CountAsAListen (4101) "Lions" NOT played long enough: Played 20.189719; needed to play 112.5 seconds.
[08-11-04 20:53:29.0904] Plugins::TrackStat::Storage::findTrack (471) Reading slimserver track: file:///Z:/My%20Personal%20Music/Alexa%20Wilkinson/Lions/02%20-%20Lions.mp3
[08-11-04 20:53:29.0965] Plugins::TrackStat::Storage::findTrack (495) findTrack(): URL: file:///Z:/My%20Personal%20Music/Alexa%20Wilkinson/Lions/02%20-%20Lions.mp3
[08-11-04 20:53:29.1060] Plugins::TrackStat::Storage::findTrack (471) Reading slimserver track: file:///Z:/My%20Personal%20Music/Alexa%20Wilkinson/Lions/02%20-%20Lions.mp3
[08-11-04 20:53:29.1116] Plugins::TrackStat::Storage::findTrack (495) findTrack(): URL: file:///Z:/My%20Personal%20Music/Alexa%20Wilkinson/Lions/02%20-%20Lions.mp3
[08-11-04 20:53:29.1139] Plugins::TrackStat::Plugin::stopTimingSong (3928) Decreasing rating by 7/100, played 20.189719 of required 112.5 seconds
[08-11-04 20:53:29.1145] Plugins::TrackStat::Plugin::rateSong (4113) Changing song rating to: 62
[08-11-04 20:53:29.1161] Plugins::TrackStat::Storage::findTrack (495) findTrack(): URL: file:///Z:/My%20Personal%20Music/Alexa%20Wilkinson/Lions/02%20-%20Lions.mp3
[08-11-04 20:53:29.1183] Plugins::TrackStat::Storage::saveRating (651) Store rating
[08-11-04 20:53:29.1190] Plugins::TrackStat::Storage::saveRating (667) Execute UPDATE track_statistics set rating=62 where url = ? or url = ?
[08-11-04 20:53:29.1210] Plugins::TrackStat::Plugin::rateSong (4123) Calling Plugins::TrackStat::Plugin
[08-11-04 20:53:29.1215] Plugins::TrackStat::Plugin::setTrackStatRating (4139) Entering setTrackStatRating
[08-11-04 20:53:29.3454] Plugins::TrackStat::Plugin::setTrackStatRating (4167) Exiting setTrackStatRating
[08-11-04 20:53:29.3464] Plugins::TrackStat::Plugin::startTimingNewSong (3757) Starting a new song
[08-11-04 20:53:29.3658] Plugins::TrackStat::Plugin::startTimingNewSong (3799) Starting to time file:///Z:/My%20Personal%20Music/Duffy/Rockferry/05.%20Duffy%20-%20Rockferry%20-%20Syrup%20&%20Honey.flac

[erland]

I think the problem is that you have the "Enable filtering on all playlists" option in Custom Skip settings enabled.

The result is that when you add tracks manually, it will check them against active filters in Custom Skip and if it matches it will be removed when it is about to start to play.

Does it work if you add a track that can't match the currently active skipping filter in the Custom Skip plugin ?

I'm guessing that you would really like the track to be played even if it matches your skipping filter ?

I'm not completely sure what the best behavior would be here, let's say we have the following scenario:

We have a skipping filter that says we don't want to play tracks rated below 3.

- If we play a Random Mix playlist we definitely want those low rated tracks skipped.
- If we play a standard saved playlist I also suspect we want those low rated tracks skipped.
- If we hit play on an artist we probably also want those low rated tracks skipped.
- If we hit play on an album I'm not sure what we want.
- If we hit play on a specific track we probably want it to be played even if it matches the skipping filter.

The problem with the last scenario is just that other people might use this to disallow adult tracks in the kids room and they probably also want to skip in the last scenario.

The problem you are seeing should only be seen when the "Enable filtering on all playlists" option is enabled. The problem when this option is enabled is that the Custom Skip plugin can't differ how the tracks are added. I could possibly add a special case so tracks added manually when a Dynamic Playlist is active is never skipped, but I'm not sure that would give the expected behavior in all the scenarios listed above.

Any suggestions on which behavior you (or someone else) would like would be appreciated.

[GeeJay]

Thanks for the suggestion, Erland. Switching that particular option to "off" seems to fix the problem. I generated a fresh random playlist using my SQLPlaylist, then added a track...this time it played, just like they used to before I upgraded to 7.2.x.

If I'm understanding your explanation correctly, the behavior I experienced seems to be different than that which you described. SC would skip any track I tried to manually add, despite it's characteristics. For example, the filter associated with that particular playlist is set to exclude any song rated 3 or worse, but even adding a 5-rated track would result in the song being skipped. It didn't seem to differentiate between "acceptable" tracks and ones that would normally be skipped during a random search. Could it be checking the track against all the filters I've created, even ones that aren't active?

I want to play around with this some more to make sure that my problem is indeed fixed, and then see if I can replicate the situation I described in the previous paragraph. If I do, I could post the results in a different thread...this seems to be more of a "Custom Skip" problem than a "Play Next" problem.

[erland]

If I'm understanding your explanation correctly, the behavior I experienced seems to be different than that which you described. SC would skip any track I tried to manually add, despite it's characteristics. For example, the filter associated with that particular playlist is set to exclude any song rated 3 or worse, but even adding a 5-rated track would result in the song being skipped. It didn't seem to differentiate between "acceptable" tracks and ones that would normally be skipped during a random search. Could it be checking the track against all the filters I've created, even ones that aren't active?

Feels strange, it would be nice to see the log from a case where it skips something that doesn't match the active filter. Remember that there might two active filters simultaneously.
1. The globally active filter that is shown as Active Filter when you goto the Custom Skip menu in the web interface
2. The filter associated with the particular playlist

The following log entries shows that the track is skipped

[08-11-04 20:53:28.9876] Plugins::CustomSkip::Plugin::executeDynamicPlayListFilter (608) Filter trackstat_rated matched
[08-11-04 20:53:28.9882] Plugins::CustomSkip::Plugin::executeDynamicPlayListFilter (616) Use skip percentage 100%
[08-11-04 20:53:28.9889] Plugins::CustomSkip::Plugin::executeDynamicPlayListFilter (644) Skip track: Lions

The first row indicates which filter item that matched, in this case it was a TrackStat based Rated filter. The last row indicates if the track was skipped or not. If the skip percentage is less than 100% it might match a filter item (the first row in the log above) but it doesn't have to actually be skipped (the last row in the log above).