Bugzilla – Bug 9078
Some MP3 files popping at start of playback.
Last modified: 2009-07-31 10:26:48 UTC
Created attachment 3764 [details] MP3 File. I have some MP3 files that played fine under 7.0.1 but I'm noticing a split-second of pop and noise upon playback with 7.1. This doesn't happen with all my MP3 files, probably only a minority now I've looked in more detail, and generally ones I haven't ripped myself. AAC and Apple Lossless are all fine. I have also just recently done a Software Update on OSX which could also be the cause, hard to say, I just know these files didn't exhibit this problem before I upgraded OSX and SqueezeCenter. Attached is an MP3 file that pops every time when played through my SB3.
Works fine for me in 7.2. Are you using native MP3 or transcoding to something else? This file has a very large image (350K) in the id3v2 tag, that's the only thing I can think of that might be the cause.
I upgraded to 7.2 - 22440 and still get the pop. However, I've now deleted the embedded album artwork and the song now plays back fine. Just gone through several of the songs I played last night and they also have over-large image files embedded. So I guess this image data is perhaps causing a bit of a stutter before playback or something? Pretty sure it didn't happen under 7.0.1 but I'll be sure to change and keep my album art to smaller files in the future. Thanks for the help. Much appreciated.
Which player do you have? Large artwork shouldn't be a problem, and I don't have any problem with this track.
It's a SB3, Firmware 107 I think. I'm running MP3 as native. I do see the SB3 flash up "Rebuffering 0%" very briefly on the problem tracks that still have large artwork.
OK, can you enable player.source debug logging and attach the log output from when you play this track?
Not very familiar with the debugging but I think this is a cut-and-paste of the starting track events. Let me know if this isn't want you want or if you need any other log output. [08-08-08 18:33:44.9462] Slim::Player::Source::playmode (309) 00:04:20:06:81:db: Switching to mode play from stop [08-08-08 18:33:44.9470] Slim::Player::Source::resetSong (1739) Resetting song buffer. [08-08-08 18:33:44.9531] Slim::Player::Source::openSong (1840) Trying to open: file:///Volumes/Fiend/Music/iTunes/iTunes%20Music/Satyricon/My%20Skin%20Is%20Cold%20(EP)/01%20My%20skin%20is%20cold.mp3 [08-08-08 18:33:44.9552] Slim::Player::Source::openSong (2049) duration: [306.337] size: [7723416] endian [] offset: [0] for file:///Volumes/Fiend/Music/iTunes/iTunes%20Music/Satyricon/My%20Skin%20Is%20Cold%20(EP)/01%20My%20skin%20is%20cold.mp3 [08-08-08 18:33:44.9565] Slim::Player::TranscodingHelper::getConvertCommand (215) undermax = 1, type = mp3, squeezebox2 = 00:04:20:06:81:db [08-08-08 18:33:44.9571] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-wma-squeezebox2-00:04:20:06:81:db [08-08-08 18:33:44.9575] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-wma-*-00:04:20:06:81:db [08-08-08 18:33:44.9579] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-wma-squeezebox2-* [08-08-08 18:33:44.9584] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-wma-*-* [08-08-08 18:33:44.9588] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-ogg-squeezebox2-00:04:20:06:81:db [08-08-08 18:33:44.9593] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-ogg-*-00:04:20:06:81:db [08-08-08 18:33:44.9597] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-ogg-squeezebox2-* [08-08-08 18:33:44.9602] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-ogg-*-* [08-08-08 18:33:44.9606] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-flc-squeezebox2-00:04:20:06:81:db [08-08-08 18:33:44.9610] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-flc-*-00:04:20:06:81:db [08-08-08 18:33:44.9615] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-flc-squeezebox2-* [08-08-08 18:33:44.9619] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-flc-*-* [08-08-08 18:33:44.9624] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-aif-squeezebox2-00:04:20:06:81:db [08-08-08 18:33:44.9630] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-aif-*-00:04:20:06:81:db [08-08-08 18:33:44.9635] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-aif-squeezebox2-* [08-08-08 18:33:44.9639] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-aif-*-* [08-08-08 18:33:44.9644] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-wav-squeezebox2-00:04:20:06:81:db [08-08-08 18:33:44.9648] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-wav-*-00:04:20:06:81:db [08-08-08 18:33:44.9653] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-wav-squeezebox2-* [08-08-08 18:33:44.9658] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-wav-*-* [08-08-08 18:33:44.9663] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-mp3-squeezebox2-00:04:20:06:81:db [08-08-08 18:33:44.9667] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-mp3-*-00:04:20:06:81:db [08-08-08 18:33:44.9672] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-mp3-squeezebox2-* [08-08-08 18:33:44.9676] Slim::Player::TranscodingHelper::checkBin (152) Checking formats for: mp3-mp3-*-* [08-08-08 18:33:44.9681] Slim::Player::TranscodingHelper::enabledFormat (119) Checking to see if mp3-mp3-*-* is enabled [08-08-08 18:33:44.9686] Slim::Player::TranscodingHelper::enabledFormat (127) There are 9 disabled formats... [08-08-08 18:33:44.9690] Slim::Player::TranscodingHelper::enabledFormat (133) Testing aif-mp3-*-* vs mp3-mp3-*-* [08-08-08 18:33:44.9695] Slim::Player::TranscodingHelper::enabledFormat (133) Testing alc-flc-*-* vs mp3-mp3-*-* [08-08-08 18:33:44.9699] Slim::Player::TranscodingHelper::enabledFormat (133) Testing alc-mp3-*-* vs mp3-mp3-*-* [08-08-08 18:33:44.9704] Slim::Player::TranscodingHelper::enabledFormat (133) Testing flc-mp3-*-* vs mp3-mp3-*-* [08-08-08 18:33:44.9708] Slim::Player::TranscodingHelper::enabledFormat (133) Testing flc-wav-*-* vs mp3-mp3-*-* [08-08-08 18:33:44.9713] Slim::Player::TranscodingHelper::enabledFormat (133) Testing mov-flc-*-* vs mp3-mp3-*-* [08-08-08 18:33:44.9717] Slim::Player::TranscodingHelper::enabledFormat (133) Testing mov-mp3-*-* vs mp3-mp3-*-* [08-08-08 18:33:44.9722] Slim::Player::TranscodingHelper::enabledFormat (133) Testing ogg-mp3-*-* vs mp3-mp3-*-* [08-08-08 18:33:44.9726] Slim::Player::TranscodingHelper::enabledFormat (133) Testing wav-wav-*-* vs mp3-mp3-*-* [08-08-08 18:33:44.9731] Slim::Player::TranscodingHelper::checkBin (160) enabled [08-08-08 18:33:44.9735] Slim::Player::TranscodingHelper::checkBin (162) Found command: - [08-08-08 18:33:44.9753] Slim::Player::TranscodingHelper::getConvertCommand (316) Matched Format: mp3 Type: mp3 Command: - [08-08-08 18:33:44.9758] Slim::Player::Source::openSong (2078) This is an mp3 file: file:///Volumes/Fiend/Music/iTunes/iTunes%20Music/Satyricon/My%20Skin%20Is%20Cold%20(EP)/01%20My%20skin%20is%20cold.mp3 [08-08-08 18:33:44.9763] Slim::Player::Source::openSong (2079) file type: mp3 format: mp3 inrate: 192 maxRate: 0 [08-08-08 18:33:44.9767] Slim::Player::Source::openSong (2080) command: - [08-08-08 18:33:44.9771] Slim::Player::Source::openSong (2099) Streaming with format: mp3 [08-08-08 18:33:44.9778] Slim::Player::Source::openSong (2113) Opening file /Volumes/Fiend/Music/iTunes/iTunes Music/Satyricon/My Skin Is Cold (EP)/01 My skin is cold.mp3 [08-08-08 18:33:44.9869] Slim::Player::Source::playmode (412) 00:04:20:06:81:db New play mode: play [08-08-08 18:33:44.9958] Slim::Player::Source::playmode (581) 00:04:20:06:81:db: Current playmode: play [08-08-08 18:33:45.2842] Slim::Player::Source::readNextChunk (2331) Sending 0 bytes of silence. [08-08-08 18:33:46.5681] Slim::Player::Source::trackStartEvent (1605) Got a track starting event [08-08-08 18:33:46.5686] Slim::Player::Source::trackStartEvent (1621) Song 0 has now started playing [08-08-08 18:33:46.5711] Slim::Player::Source::trackStartEvent (1649) Song queue is now 0 [08-08-08 18:33:46.6251] Slim::Player::Source::outputUnderrun (800) 00:04:20:06:81:db: Output buffer underrun (decoder: 708748 / output: 0) [08-08-08 18:33:46.6257] Slim::Player::Source::playmode (309) 00:04:20:06:81:db: Switching to mode pause from play [08-08-08 18:33:46.6271] Slim::Player::Source::playmode (412) 00:04:20:06:81:db New play mode: pause [08-08-08 18:33:46.6286] Slim::Player::Source::playmode (581) 00:04:20:06:81:db: Current playmode: pause [08-08-08 18:33:47.6331] Slim::Player::Source::rebuffer (900) Rebuffering: 839039 / 120000 [08-08-08 18:33:47.6337] Slim::Player::Source::playmode (309) 00:04:20:06:81:db: Switching to mode play from pause [08-08-08 18:33:47.6349] Slim::Player::Source::playmode (412) 00:04:20:06:81:db New play mode: resume [08-08-08 18:33:47.6362] Slim::Player::Source::playmode (430) 00:04:20:06:81:db: Resume, resetting mode: play [08-08-08 18:33:47.6385] Slim::Player::Source::playmode (581) 00:04:20:06:81:db: Current playmode: resume [08-08-08 18:34:21.1553] Slim::Player::Source::playmode (309) 00:04:20:06:81:db: Switching to mode pause from play [08-08-08 18:34:21.1567] Slim::Player::Source::playmode (412) 00:04:20:06:81:db New play mode: pause [08-08-08 18:34:21.1580] Slim::Player::Source::playmode (581) 00:04:20:06:81:db: Current playmode: pause [08-08-08 18:38:38.9626] Slim::Player::Source::playmode (309) 00:04:20:06:81:db: Switching to mode stop from pause [08-08-08 18:38:38.9667] Slim::Player::Source::playmode (412) 00:04:20:06:81:db New play mode: stop [08-08-08 18:38:38.9673] Slim::Player::Source::playmode (461) 00:04:20:06:81:db: Stopping and clearing out old chunks
Hmm, the interesting part here is this track has an offset of 0. On the above attached track, the offset should be around 350K, past the leading artwork. The player should still decode this fine but such a large amount of unplayable data before the audio may cause problems with autostart. Can you check the offset used on the attached file? If it's also 0, we need to figure out why it's not being scanned properly.
QA should try and reproduce this too.
Hey Andy, as these things often go, I can't now reproduce the problem with the attached file. :-) I copied it back into iTunes, rescanned, et voila, no playback pop. So I did the same with the Satyricon song that is referenced in the log, I deleted it from my library, then copied it back in, and yep, the problem is gone. The offset is as you predicted: [08-08-08 21:56:28.5218] Slim::Player::Source::openSong (2049) duration: [306.337] size: [7352111] endian [] offset: [371177] All my music is stored on a USB disk and so I think perhaps we might just have an odd file system quirk or something. The fact that the SB3 is now playing back exactly the same data without any issue suggests it's nothing to worry about at your end. It may well be some disk-fart because I've tried some other tunes (mp3s) tonight with large artwork embedded and they play fine. And yet others exhibit the problem so I wonder if there's some part of the disk that has got corrupted, it's quite possible I've had to disconnect it a few times with the power on. Sorry if this has wasted your time.
OK, glad it seems to be working for you now.
Reduce number of active targets for SC