Bugzilla – Bug 1242
First song skipped on play in random iTunes playlist
Last modified: 2008-08-18 10:54:16 UTC
When starting up a new playlist, it often (but not always) skips the first song and throws this error: Use of uninitialized value in numeric gt (>) at /PerlApp/Slim/Player/Source.pm line 1642. Use of uninitialized value in subtraction (-) at /PerlApp/Slim/Player/Source.pm line 1644. Use of uninitialized value in numeric gt (>) at /PerlApp/Slim/Player/Source.pm line 1654. Reproducible steps: I can reproduce it every single time, here are the steps that I've taken to get to it. I don't run slimserver as a service, but as the slim.exe file, so it's easy to restart by killing the window and relaunching while keeping the interface window open. I also play everything in song shuffle mode and repeat all. Steps: - Restart server - Click Add To Playlist from any iTunes playlist (I don't have any others, but size doesn't seem to be an issue as I've tried from ~100 to >3000) - The playlist queues up with the first random song in stopped mode, but the playlist (ie, everything below the Download and Clear links in Fishbone) stays blank white, odd. - Hit play on the interface and the error is thrown, the first song is skipped, the second song begins, and the playlist screen fills in
Vidur thinks that this is fixed in the latest 6.0.2 nightly release. Can you install that and verify that the bug is fixed? Reopen the bug if it's still an issue. Thanks!
Nope, I can still follow the same steps and get the same result. Reinstalled with a reboot, but no change.
I'm not able to recreate this with the latest 6.0.2 nightly. When this does happen (you imply that it is intermittent), is there any pattern to the type of song that's first on the list? Also, would it be possible for you to get a log with the --d_source debug flag on?
Also, could you confirm that the Now Playing list is empty before you do the Add to Playlist? And you have Shuffle by Song turned on, correct?
I've tried with the 4/20 and 4/21 Windows installer nightlies. It is not intermittent. I originally thought that it was until I was able to nail down the procedure detailed here. It only happens when Play is initiated by the web interface, not when Play is hit on the remote. There's no pattern to the initial song, since the playlist comes up completely randomized. I use a very large playlist for this, so it's a pretty solid cross section of my (admittedly odd) library. The Now Playing list is empty and Shuffle by Song is on. If it would make things easier, I could have you watch exactly what I do via Netmeeting. This seems to be the relevant log bit: 2005-04-21 14:24:52.4916 00:04:20:05:5e:76: Switching to mode play from stop 2005-04-21 14:24:52.4935 openSong on: file:///D:/MP3s/The%20Galactic%20Cowboys/Machine%20Fish/The%20Galactic%20Cowboys%20-%20Psychotic%20Companion.mp3 2005-04-21 14:24:52.5010 openSong: getting duration 452.179, size 7234456, endian and offset 2048 for file:///D:/MP3s/The%20Galactic%20Cowboys/Machine%20Fish/The%20Galactic%20Cowboys%20-%20Psychotic%20Companion.mp3 2005-04-21 14:24:52.5018 Setting maxBitRate for Squeezebox to: 320 2005-04-21 14:24:52.5029 Setting maxBitRate for Squeezebox to: 320 2005-04-21 14:24:52.5058 Setting maxBitRate for Squeezebox to: 320 2005-04-21 14:24:52.5071 Setting maxBitRate for Squeezebox to: 320 2005-04-21 14:24:52.5108 undermax = 1, type = mp3, squeezebox = 00:04:20:05:5e:76, lame = C:\Program Files\SlimServer\server\Bin\lame.exe 2005-04-21 14:24:52.5117 checking formats for: mp3-aif-squeezebox-00:04:20:05:5e:76 2005-04-21 14:24:52.5120 Checking to see if mp3-aif-squeezebox-00:04:20:05:5e:76 is enabled 2005-04-21 14:24:52.5123 enabled 2005-04-21 14:24:52.5125 checking formats for: mp3-aif-*-00:04:20:05:5e:76 2005-04-21 14:24:52.5127 Checking to see if mp3-aif-*-00:04:20:05:5e:76 is enabled 2005-04-21 14:24:52.5130 enabled 2005-04-21 14:24:52.5133 checking formats for: mp3-aif-squeezebox-* 2005-04-21 14:24:52.5136 Checking to see if mp3-aif-squeezebox-* is enabled 2005-04-21 14:24:52.5139 enabled 2005-04-21 14:24:52.5141 checking formats for: mp3-aif-*-* 2005-04-21 14:24:52.5143 Checking to see if mp3-aif-*-* is enabled 2005-04-21 14:24:52.5145 enabled 2005-04-21 14:24:52.5148 checking formats for: mp3-wav-squeezebox-00:04:20:05:5e:76 2005-04-21 14:24:52.5150 Checking to see if mp3-wav-squeezebox-00:04:20:05:5e:76 is enabled 2005-04-21 14:24:52.5153 enabled 2005-04-21 14:24:52.5155 checking formats for: mp3-wav-*-00:04:20:05:5e:76 2005-04-21 14:24:52.5157 Checking to see if mp3-wav-*-00:04:20:05:5e:76 is enabled 2005-04-21 14:24:52.5159 enabled 2005-04-21 14:24:52.5161 checking formats for: mp3-wav-squeezebox-* 2005-04-21 14:24:52.5163 Checking to see if mp3-wav-squeezebox-* is enabled 2005-04-21 14:24:52.5166 enabled 2005-04-21 14:24:52.5168 checking formats for: mp3-wav-*-* 2005-04-21 14:24:52.5170 Checking to see if mp3-wav-*-* is enabled 2005-04-21 14:24:52.5172 enabled 2005-04-21 14:24:52.5174 checking formats for: mp3-mp3-squeezebox-00:04:20:05:5e:76 2005-04-21 14:24:52.5177 Checking to see if mp3-mp3-squeezebox-00:04:20:05:5e:76 is enabled 2005-04-21 14:24:52.5179 enabled 2005-04-21 14:24:52.5180 checking formats for: mp3-mp3-*-00:04:20:05:5e:76 2005-04-21 14:24:52.5182 Checking to see if mp3-mp3-*-00:04:20:05:5e:76 is enabled 2005-04-21 14:24:52.5185 enabled 2005-04-21 14:24:52.5186 checking formats for: mp3-mp3-squeezebox-* 2005-04-21 14:24:52.5188 Checking to see if mp3-mp3-squeezebox-* is enabled 2005-04-21 14:24:52.5190 enabled 2005-04-21 14:24:52.5191 checking formats for: mp3-mp3-*-* 2005-04-21 14:24:52.5193 Checking to see if mp3-mp3-*-* is enabled 2005-04-21 14:24:52.5195 enabled 2005-04-21 14:24:52.5196 Found command: - 2005-04-21 14:24:52.5203 Setting maxBitRate for Squeezebox to: 320 2005-04-21 14:24:52.5208 Setting maxBitRate for Squeezebox to: 320 2005-04-21 14:24:52.5239 Matched Format: mp3 Type: mp3 Command: - 2005-04-21 14:24:52.5245 openSong: this is an mp3 file: file:///D:/MP3s/The%20Galactic%20Cowboys/Machine%20Fish/The%20Galactic%20Cowboys%20-%20Psychotic%20Companion.mp3 2005-04-21 14:24:52.5248 file type: mp3 format: mp3 inrate: 128 maxRate: 320 2005-04-21 14:24:52.5250 command: - 2005-04-21 14:24:52.5254 openSong: opening file D:\MP3s\The Galactic Cowboys\Machine Fish\The Galactic Cowboys - Psychotic Companion.mp3 2005-04-21 14:24:52.5261 seeking in 2048 into D:\MP3s\The Galactic Cowboys\Machine Fish\The Galactic Cowboys - Psychotic Companion.mp3 2005-04-21 14:24:52.5274 Streaming with format: mp3 2005-04-21 14:24:52.7340 00:04:20:05:5e:76 New play mode: play 2005-04-21 14:24:52.7392 00:04:20:05:5e:76: Current playmode: play 2005-04-21 14:24:52.8054 Setting maxBitRate for Squeezebox to: 320 2005-04-21 14:24:52.8062 Setting maxBitRate for Squeezebox to: 320 2005-04-21 14:24:52.8915 We need to send 0 seconds of silence... 2005-04-21 14:24:52.8920 sending 0 bytes of silence 2005-04-21 14:24:52.8929 Reduced chunksize to 0 at end of file ( - 0) *error is thrown here, but not showing in log, same as in initial description* 2005-04-21 14:24:52.8940 end of file or error on socket, opening next song, (song pos: 0(tell says: . 2048), totalbytes: ) 2005-04-21 14:24:52.8943 opening next song...
Any chance you could zip up the entire log (from SlimServer startup till the point where this bug manifests itself) and attach it to this bug? I'm still not able to recreate, but I've got a guess to what the problem might be. I'm also going to attach a proposed code patch. If you're set up with ActiveState Perl and can apply it, I'd appreciate feedback on whether it makes a difference. If not, I can probably apply it to the nightlies, since it's pretty safe.
Created attachment 446 [details] proposed (speculative) fix
Created attachment 447 [details] log file Here you go. I don't have Perl set up, but if it's something I can hand-edit it, I'll give it a try.
Made the two changes that I saw in the patch, but it doesn't seem to have done the trick. I'm assuming I just need to make the changes and restart the server, correct?
making the change to code works for slimserver.pl, but not slim.exe. If you are using the windows service, it would have to be in a nightly build. Otherwise, you can download activePerl and use slimserver.pl.
OK, I ran slimserver.pl instead of slim.exe, but got the same result, patch or no.
Sorry to do this to you again. Can you post a patch from running slimserver.pl from the command line with --d_source as an argument? That is: perl slimserver.pl --d_source I'd like to see the log at startup.
Created attachment 451 [details] Log file 2 Not a problem, here you go. Let me know if you need anything else.
Created attachment 475 [details] another attempt at fixing I saw the problem while debugging another issue, but haven't been able to successfully recreate it well enough to debug. But I have another proposed fix, based on what little I saw. Any chance you could try it?
Big crash. Here's the error: 2005-05-01 13:06:44.7187 Backtrace: frame 0: Slim::Player::Source::playmode (C:/Program Files/SlimServer/server/S lim/Control/Command.pm line 597) frame 1: Slim::Control::Command::execute (C:/Program Files/SlimServer/server/ Slim/Web/HTTP.pm line 663) frame 2: Slim::Web::HTTP::processURL (C:/Program Files/SlimServer/server/Slim /Web/HTTP.pm line 531) frame 3: Slim::Web::HTTP::processHTTP (C:/Program Files/SlimServer/server/Sli m/Networking/Select.pm line 115) frame 4: Slim::Networking::Select::select (slimserver.pl line 619) frame 5: main::idle (slimserver.pl line 562) frame 6: main::main (slimserver.pl line 1124) 2005-05-01 13:06:44.7213 00:04:20:05:5e:76: Switching to mode play from stop Can't locate object method "streamingSongIndex" via package "Slim::Player::Squee zeboxG" at C:/Program Files/SlimServer/server/Slim/Player/Source.pm line 927.
Created attachment 477 [details] fixed version of previous patch Ack. Well...the good news is that you're hitting the codepath that I expected. Here's a beter patch.
That appears to have done the trick, as far as I can tell. Need any more input from me?
Vidur: was this committed?
thanks. the "skip by album" is filed separately as bug 460.
This bug was marked resolved in Slimserver 6.1, which is several versions ago. If you're still seeing this bug, please re-open it. Thanks!