Debugging help re Vista m4a issue, please

[Matt Shelton]

Hi there. Ever since doing a clean install from XP SP2 to 32-bit Vista a few weeks ago, I'm having major problems playing m4a files (95% of my library), but no problems playing mp3 files. The m4a files either never play or take 10 to 15 seconds to start playing after starting. On XP, I never had even the slightest problem ever with Slimserver. I'm having the identical problems now, be it SS 6.3.1, 6.5.1 or 6.5.2. I've also installed the lastest socketwrapper per some threads I've seen here. I've even tried to run all SS-related exe files in "XP Compatability mode", but no luck. I've also completely uninstalled and reinstalled iTunes and Quicktime, and I've completely rescanned my library - all to no avail.

I'm pasting in info re my debugging efforts: one for a mp3 file that played successfully and one for a m4a file that did not play. Unfortunately, I'm not sure which debug codes will show the best information, but I've given it a good shot. I would greatly appreciate it if someone could look at the debugging info to see if you can figure out the issue! Thanks.

Unsuccesful Playback of m4a song
ned --channels 2 --bps 16 --sample-rate 44100 - |"
2007-04-04 07:37:15.6605 openSong: Streaming with format: flc
2007-04-04 07:37:15.7006 00:04:20:06:25:0e New play mode: play
2007-04-04 07:37:15.7079 _checkValidity: Checking to see if file:///F:/iTunes/iTunes%20Music/Moby/18/01%20We%20Are%20All%20Made%20Of%20Stars.m4a has changed.
2007-04-04 07:37:15.7081 _hasChanged: Checking for [F:\iTunes\iTunes Music\Moby\18\01 We Are All Made Of Stars.m4a] - size & timestamp.
2007-04-04 07:37:15.7103 00:04:20:06:25:0e: Current playmode: play
2007-04-04 07:37:15.8604 Pipeline reader connected
2007-04-04 07:37:16.0254 readlen undef: (Unknown error)10054
2007-04-04 07:37:16.0255 end of file or error on socket, opening next song, (song pos: 0(tell says: . 0), totalbytes: 0)
2007-04-04 07:37:16.0256 Didn't stream any bytes for this song, so just mark it as played
2007-04-04 07:37:16.0257 opening next song...
2007-04-04 07:37:16.0273 the next song is number 0, was 0
2007-04-04 07:37:16.0280 undermax = 1, type = mov, squeezebox2 = 00:04:20:06:25:0e
2007-04-04 07:37:16.0282 checking formats for: mov-wma-squeezebox2-00:04:20:06:25:0e
2007-04-04 07:37:16.0283 checking formats for: mov-wma-*-00:04:20:06:25:0e
2007-04-04 07:37:16.0284 checking formats for: mov-wma-squeezebox2-*
2007-04-04 07:37:16.0285 checking formats for: mov-wma-*-*
2007-04-04 07:37:16.0286 checking formats for: mov-ogg-squeezebox2-00:04:20:06:25:0e
2007-04-04 07:37:16.0287 checking formats for: mov-ogg-*-00:04:20:06:25:0e
2007-04-04 07:37:16.0287 checking formats for: mov-ogg-squeezebox2-*
2007-04-04 07:37:16.0288 checking formats for: mov-ogg-*-*
2007-04-04 07:37:16.0289 checking formats for: mov-flc-squeezebox2-00:04:20:06:25:0e
2007-04-04 07:37:16.0290 checking formats for: mov-flc-*-00:04:20:06:25:0e
2007-04-04 07:37:16.0291 checking formats for: mov-flc-squeezebox2-*
2007-04-04 07:37:16.0292 checking formats for: mov-flc-*-*
2007-04-04 07:37:16.0293 Checking to see if mov-flc-*-* is enabled
2007-04-04 07:37:16.0293 enabled
2007-04-04 07:37:16.0294 Found command: [mov123] $FILE$ | [flac] -cs --totally-silent --compression-level-0 --endian big --sign signed --channels 2 --bps 16 --sample-rate 44100 -
2007-04-04 07:37:16.0296 Matched Format: flc Type: mov Command: [mov123] $FILE$ | [flac] -cs --totally-silent --compression-level-0 --endian big --sign signed --channels 2 --bps 16 --sample-rate 44100 -
2007-04-04 07:37:16.0297 playing out before starting next song. (old format: flc, new: flc)
2007-04-04 07:37:16.0298 00:04:20:06:25:0e: Switching to mode playout-play from play
2007-04-04 07:37:16.0301 00:04:20:06:25:0e New play mode: playout-play
2007-04-04 07:37:16.0310 00:04:20:06:25:0e: Current playmode: playout-play
2007-04-04 07:37:16.0311 No pending chunks - we're dropping the streaming connection
2007-04-04 07:37:16.0317 00:04:20:06:25:0e: Can't opennext, returning no chunk.
2007-04-04 07:37:16.0352 00:04:20:06:25:0e: Decoder underrun while this mode: playout-play

Successful Playback of mp3 song

file:///F:/iTunes/iTunes%20Music/dZihan%20&%20Kamien/Freaks%20and%20Icons/10%20Ocean%20Air.mp3 has changed.
2007-04-04 07:28:42.7598 Got /F:/iTunes/iTunes%20Music/dZihan%20&%20Kamien/Freaks%20and%20Icons/10%20Ocean%20Air.mp3 from file url file:///F:/iTunes/iTunes%20Music/dZihan%20&%20Kamien/Freaks%20and%20Icons/10%20Ocean%20Air.mp3
2007-04-04 07:28:42.7611 extracted: F:\iTunes\iTunes Music\dZihan & Kamien\Freaks and Icons\10 Ocean Air.mp3 from file:///F:/iTunes/iTunes%20Music/dZihan%20&%20Kamien/Freaks%20and%20Icons/10%20Ocean%20Air.mp3
2007-04-04 07:28:42.7613 _hasChanged: Checking for [F:\iTunes\iTunes Music\dZihan & Kamien\Freaks and Icons\10 Ocean Air.mp3] - size & timestamp.
2007-04-04 07:28:42.7639 _checkValidity: Re-reading tags from file:///F:/iTunes/iTunes%20Music/dZihan%20&%20Kamien/Freaks%20and%20Icons/10%20Ocean%20Air.mp3 as it has changed.
2007-04-04 07:28:42.8150
2007-04-04 07:28:42.8151 newTrack(): New Track: [file:///F:/iTunes/iTunes%20Music/dZihan%20&%20Kamien/Freaks%20and%20Icons/10%20Ocean%20Air.mp3]
2007-04-04 07:28:42.8152 newTrack(): readTags is 1
2007-04-04 07:28:42.8154 mp3 file type for F:\iTunes\iTunes Music\dZihan & Kamien\Freaks and Icons\10 Ocean Air.mp3
2007-04-04 07:28:42.8207 findFrameBoundaries: start: [27054] end: [7343657]
2007-04-04 07:28:42.8289 newTrack(): Created track 'Ocean Air' (id: [11943])
2007-04-04 07:28:43.3588 _checkValidity: Checking to see if file:///F:/iTunes/iTunes%20Music/dZihan%20&%20Kamien/Freaks%20and%20Icons/10%20Ocean%20Air.mp3 has changed.
2007-04-04 07:28:43.3590 _hasChanged: Checking for [F:\iTunes\iTunes Music\dZihan & Kamien\Freaks and Icons\10 Ocean Air.mp3] - size & timestamp.
2007-04-04 07:28:46.7773 00:04:20:06:25:0e: Switching to mode stop from stop
2007-04-04 07:28:46.7774 Already in playmode stop : ignoring mode change
2007-04-04 07:28:46.7776 Adding song index 0 to song queue
2007-04-04 07:28:46.7777 Clearing out song queue first
2007-04-04 07:28:46.7779 Song queue is now 0
2007-04-04 07:28:46.7894 00:04:20:06:25:0e: Switching to mode stop from stop
2007-04-04 07:28:46.7896 Already in playmode stop : ignoring mode change
2007-04-04 07:28:46.7897 Adding song index 0 to song queue
2007-04-04 07:28:46.7898 Clearing out song queue first
2007-04-04 07:28:46.7899 Song queue is now 0
2007-04-04 07:28:46.7903 00:04:20:06:25:0e: Switching to mode play from stop
2007-04-04 07:28:46.7991 openSong: duration: [325.407] size: [7316604] endian [] offset: [27054] for file:///F:/iTunes/iTunes%20Music/dZihan%20&%20Kamien/Freaks%20and%20Icons/10%20Ocean%20Air.mp3
2007-04-04 07:28:46.7998 undermax = 1, type = mp3, squeezebox2 = 00:04:20:06:25:0e
2007-04-04 07:28:46.8021 Checking to see if mp3-mp3-*-* is enabled
2007-04-04 07:28:46.8022 enabled
2007-04-04 07:28:46.8023 Found command: -
2007-04-04 07:28:46.8024 Matched Format: mp3 Type: mp3 Command: -
2007-04-04 07:28:46.8025 openSong: this is an mp3 file: file:///F:/iTunes/iTunes%20Music/dZihan%20&%20Kamien/Freaks%20and%20Icons/10%20Ocean%20Air.mp3
2007-04-04 07:28:46.8026 file type: mp3 format: mp3 inrate: 179 maxRate: 0
2007-04-04 07:28:46.8027 command: -
2007-04-04 07:28:46.8029 openSong: opening file F:\iTunes\iTunes Music\dZihan & Kamien\Freaks and Icons\10 Ocean Air.mp3
2007-04-04 07:28:46.8033 openSong: seeking in 27054 into F:\iTunes\iTunes Music\dZihan & Kamien\Freaks and Icons\10 Ocean Air.mp3
2007-04-04 07:28:46.8046 MP3 file was not encoded with LAME, will not play back gapless
2007-04-04 07:28:46.8054 openSong: Streaming with format: mp3
2007-04-04 07:28:46.8096 00:04:20:06:25:0e New play mode: play
2007-04-04 07:28:46.8115 00:04:20:06:25:0e: Current playmode: play
2007-04-04 07:28:46.9168 _checkValidity: Checking to see if file:///F:/iTunes/iTunes%20Music/dZihan%20&%20Kamien/Freaks%20and%20Icons/10%20Ocean%20Air.mp3 has changed.
2007-04-04 07:28:46.9169 _hasChanged: Checking for [F:\iTunes\iTunes Music\dZihan & Kamien\Freaks and Icons\10 Ocean Air.mp3] - size & timestamp.
2007-04-04 07:28:47.0641 Use of uninitialized value in concatenation (.) or string at /PerlApp/Slim/Schema.pm line 952.
2007-04-04 07:28:47.0644 Merging entry for clientplaylist://00:04:20:06:25:0e readTags is: []
2007-04-04 07:28:47.0647 Updating clientplaylist://00:04:20:06:25:0e : title to Now Playing - Downstairs
2007-04-04 07:28:47.0650 Updating clientplaylist://00:04:20:06:25:0e : year to 0
2007-04-04 07:28:47.0652 Updating clientplaylist://00:04:20:06:25:0e : content_type to cpl
2007-04-04 07:28:47.0654 Updating clientplaylist://00:04:20:06:25:0e : remote to 0
2007-04-04 07:28:47.0656 Updating clientplaylist://00:04:20:06:25:0e : titlesearch to NOW PLAYING DOWNSTAIRS
2007-04-04 07:28:47.0658 Updating clientplaylist://00:04:20:06:25:0e : titlesort to NOW PLAYING DOWNSTAIRS
2007-04-04 07:28:47.0660 Updating clientplaylist://00:04:20:06:25:0e : rating to 0
2007-04-04 07:28:47.0876 We need to send 0 seconds of silence...
2007-04-04 07:28:47.0877 sending 0 bytes of silence
2007-04-04 07:28:47.2424 Got a track starting event
2007-04-04 07:28:47.2425 Song 0 has now started playing
2007-04-04 07:28:47.2430 Song queue is now 0
2007-04-04 07:28:47.2436 Got a track starting event
2007-04-04 07:28:47.2437 Song 0 has now started playing

[bpa]

The error message below is typical of the socketwrapper problem.
2007-04-04 07:37:16.0254 readlen undef: (Unknown error)10054

What socketwrapper are you using - I know you have tried a number but for this debug log the version is important ?

Did you tell you security s/w (e.g. anti Virus, anti spyware, anti IM , firewall) that socketwrapper is a trusted app and allowed to network as it pleases and eachtime you changed socketwrapper you re-entered the info into the security s/w ?

Note playing an MP3 file does not use socketwrapper.

[Matt Shelton]

Thanks BPA. I'm using the socketwrapper that I found here:

http://homepage.eircom.net/~altondsl...2_20060220.zip

I use McAfee's firewall/antivirus, and I've given socketwrapper.exe "full access" in McAfee's Program Permissions (is there perhaps a related port I need to open up?).

I also ran SS with McAfee turned off, and I had the same problem.

Is there another version of socketwrapper I should try?

[bpa]

That socketwrapper is effectively the latest that overcame problem in XP with security s/w. A number of Vista users have found that it seems to fix a similar problem with Vista. If it is a problem related to McAfee - disabling is not enough to undo its effects - you have to uninstall it.

There is a catch-22 situation - SS 6.5.1 is the first version that uses socketwrapper for transcoding and socketwrapper generates debug messages for it's console window. However when socketwrapper is launched by 6.5.1 the console window is disabled so the debug info can't be seen.

What I find strange is that 6.3.1 didn't work - it doesn't use socketwrapper so there may be a different problem.

Was the debug log from 6.3.1 or 6.5.1/6.5.2 ? if the 6.5.1/6.5.2 can you repeat with d_source enabled and show more earlier messages as some seem to be missing.

[Matt Shelton]

Thanks BPA. The log that I posted was from 6.5.2. I experienced the identical issue - m4a's take 15 seconds to start playing after pressing play while mp3's start playing instantaneoulsy - under 6.3.1, 6.5.0 and 6.5.1 (historically, prior to upgrading to Vista, I had been using 6.3.1, as I had issues the first time I installed 6.5.0 with XP, so I simply reverted back to what had been working). When I changed just yesterday from 6.5.1 to 6.5.2 to see if that would solve the issue, instead of taking 15 seconds to start playing, the m4a's simply didn't play at all.

I've also just tested 6.5.0 without McAfee installed - same problem.

[bpa]

That's a brave thing putting an e-mail address on a forum - you could have PM'ed me. I'll mail you my address.

Alternatively you can attached log files zipped - log files compress very well.

A couple of points - the 15 secs delay before playing and now nothing - that is definitely a different problem and I wonder whether a timeout has started to interfere.

Regarding 6.3.1 - There is a faint possibility that it was built using an ActiveState build which was not fully Vista ready.

So the moment I think all future test should be with 6.5.2 as that is using very latest ActiveState build.

[Matt Shelton]

Thanks BPA. Re testing via 6.5.2 vs. 6.5.1 or 6.5.0: at least my m4a's will play using 6.5.0 or 6.5.1 - they won't play at all with 6.5.2. I have 6.5.0 installed right now. Im attaching a zip file of the debug report using d_source, tested on 6.5.0.

[bpa]

I'm working on getting a build of 6.5.2 slim.exe which will open a debug window on socketwrapper. I also have an update to socketwrapper, no functionality change but has more messages. They won't be ready for a few hours.

I'll look at the log file first in case I don't have to make the special version of slim.exe

[bpa]

Below are debug verison but before using them I have comments about the log.

There are no timestamps in the log you attached - did you remove them ? If not the last time I saw this happen the installation was corrupt.

When you installed different version, did you delete all traces of previous installation including prefs file and database ?

To use debug versions.

You can download special builds of a 6.5.2 slim.exe and socketwrapper.

http://homepage.eircom.net/~altondsl...wrapper013.zip
http://homepage.eircom.net/~altondsl...im652debug.zip

1. Do a clean install of latest slimser 6.5.2 - ideally into a new directory name (e.g. slimserver652v20070405)
2. Startup and build database
3. Test that m4a playing still has the problem
4. Stop slimserver and stop slimtray
5. Replace slim.exe and socketwrapper.exe by the debug version.
6. open a cmd window - change layout to 250 wide by 1000 long.
7. cd to slimserver server directory
8. run slim.exe
9. from web interface - open debug window, enable d_source
10. make sure repeat is Off.
11. play one m4a track.
12. After it plays or 2 mins if it doesn't - stop slim.exe, copy cmd window log to a file and post.

[Matt Shelton]

Thanks BPA. I'll take a look at this this weekend and let you know how it works out!