Bugzilla – Bug 6672
Songs often restart
Last modified: 2009-09-08 09:20:07 UTC
Using the version 7 beta, I have a problem with songs often restarting. The problem is intermittent, and I have not been able to detect a pattern. The music plays fine; it is just that often (once per hour or so) a song experiences a restart during playing. On the "second attempt" the song plays normally. Details: SqueezeCenter Version: 7.0 - 16284 - Red Hat - EN - utf8 Running on Fedora 7, automatically updated every night with yum. (In case it matters, SqueezeCenter runs in a virtual machine under VMWare Server 1.02, with the host being (again) Fedora 7). Squeezebox version 3, Firmware 86, connected via 1Gbps wired network. I'm not sure whether the problem is with the Squeezebox or with SqueezeCenter. I have enabled some debugging in the server, and can see these lines around the time of the restart: [08-01-19 21:13:22.3388] Slim::Control::Request::notifyFromArray (772) (client disconnect) [08-01-19 21:13:22.4251] Slim::Control::Request::dump (2200) Request: Query [00:04:20:12:29:24->status] from JSONRPC (Dispatchable) [08-01-19 21:13:22.4282] Slim::Control::Request::dump (2204) Param: [_index] = [-] [08-01-19 21:13:22.4348] Slim::Control::Request::dump (2204) Param: [_quantity] = [1] [08-01-19 21:13:22.4380] Slim::Control::Request::dump (2204) Param: [tags] = [uB] [08-01-19 21:13:22.5074] Slim::Networking::Slimproto::slimproto_accept (176) Accepted connection from: [172.16.1.180:47701] [08-01-19 21:13:22.5272] Slim::Networking::Slimproto::slimproto_accept (179) Setting timer in 5 seconds to close bogus connection [08-01-19 21:13:22.5752] Slim::Control::Request::dump (2200) Request: Query [00:04:20:12:29:24->status] from JSONRPC (Dispatchable) [08-01-19 21:13:22.5881] Slim::Control::Request::dump (2204) Param: [_index] = [-] [08-01-19 21:13:22.5914] Slim::Control::Request::dump (2204) Param: [_quantity] = [1] [08-01-19 21:13:22.5939] Slim::Control::Request::dump (2204) Param: [tags] = [uB] [08-01-19 21:13:22.6518] Slim::Networking::Slimproto::_hello_handler (836) Killing bogus player timer. [08-01-19 21:13:22.6569] Slim::Networking::Slimproto::_hello_handler (870) Squeezebox says hello: Deviceid: 4 revision: 86 mac: 00:04:20:12:29:24 uuid: 00000000000000000000000000000000 bitmapped: 32768 reconnect: 0 wlan_channellist: 0000 [08-01-19 21:13:22.6591] Slim::Networking::Slimproto::_hello_handler (881) Squeezebox also says: bytes_received: 54632592 [08-01-19 21:13:22.6630] Slim::Networking::Slimproto::_hello_handler (1012) Hello from existing client: 00:04:20:12:29:24 on ipport: 172.16.1.180:47701 [08-01-19 21:13:22.6793] Slim::Control::Request::unsubscribe (757) Request from: Slim::Player::Source::repeatCallback - (6 listeners) [08-01-19 21:13:22.6898] Slim::Player::Squeezebox::stream (800) stream called: q paused: undef format: undef url: undef [08-01-19 21:13:22.6930] Slim::Player::Squeezebox::stream (1083) Starting with decoder with format: m autostart: 0 threshold: 255 samplesize: ? samplerate: ? endian: ? channels: ? [08-01-19 21:13:22.6954] Slim::Player::Squeezebox::stream (1116) flags: 0 [08-01-19 21:13:22.7041] Slim::Player::Squeezebox::stream (1142) sending strm frame of length: 24 request string: [] [08-01-19 21:13:23.2796] Slim::Control::Request::notifyFromArray (772) (playlist open file:///mnt/mmedia/Music/Classical/Conjunto%20Ibe%CC%81rico/Conjunto%20Ibe%CC%81rico/01%20Claudio%20Pietro,%20Ciamando%20por%20la%20aventura.m4a) [08-01-19 21:13:23.3312] Slim::Control::Request::unsubscribe (757) Request from: Slim::Player::Source::repeatCallback - (6 listeners) [08-01-19 21:13:23.3966] Slim::Player::Squeezebox::stream (800) stream called: s paused: undef format: flc url: file:///mnt/mmedia/Music/Classical/Conjunto%20Ibe%CC%81rico/Conjunto%20Ibe%CC%81rico/01%20Claudio%20Pietro,%20Ciamando%20por%20la%20aventura.m4a [08-01-19 21:13:23.5735] Slim::Player::Squeezebox::stream (1083) Starting with decoder with format: f autostart: 1 threshold: 255 samplesize: ? samplerate: ? endian: ? channels: ? [08-01-19 21:13:23.5766] Slim::Player::Squeezebox::stream (1116) flags: 0 [08-01-19 21:13:23.5792] Slim::Player::Squeezebox::stream (1142) sending strm frame of length: 76 request string: [GET /stream.mp3?player=00:04:20:12:29:24 HTTP/1.0 ] [08-01-19 21:13:23.7707] Slim::Control::Request::notifyFromArray (772) (client reconnect) [08-01-19 21:13:23.9269] Slim::Control::Request::notifyFromArray (772) (prefset server currentSong 7) [08-01-19 21:13:24.0347] Slim::Player::Squeezebox::stream (800) stream called: t paused: undef format: undef url: undef [08-01-19 21:13:24.0398] Slim::Player::Squeezebox::stream (1083) Starting with decoder with format: m autostart: 1 threshold: 255 samplesize: ? samplerate: ? endian: ? channels: ? [08-01-19 21:13:24.0547] Slim::Player::Squeezebox::stream (1116) flags: 0 [08-01-19 21:13:24.0611] Slim::Player::Squeezebox::stream (1142) sending strm frame of length: 24 request string: [] [08-01-19 21:13:24.2221] Slim::Control::Request::dump (2200) Request: Query [00:04:20:12:29:24->status] from JSONRPC (Dispatchable) [08-01-19 21:13:24.2373] Slim::Control::Request::dump (2204) Param: [_index] = [-] [08-01-19 21:13:24.2416] Slim::Control::Request::dump (2204) Param: [_quantity] = [1] [08-01-19 21:13:24.2450] Slim::Control::Request::dump (2204) Param: [tags] = [uB] [08-01-19 21:13:24.6200] Slim::Control::Request::dump (2200) Request: Query [00:04:20:12:29:24->status] from JSONRPC (Dispatchable)
Alan: does this make sense to you?
The fact that you see Slim::Networking::Slimproto::_hello_handler suggests that the Slimproto connection between SC and the player is getting broken. Play restarts as it is reestablished. I have no idea what could be interrupting your netwrok connection. Can you go back another 30s or so in the logs before the Slim::Networking::Slimproto::slimproto_accept?
FWIW, I was seeing this up until a couple months ago with an SB2 and commented on it in the beta forum. The SB2 would reboot at just about the same point during playback of a particular song. Fairly random, but once a particular song began 'causing' the behavior, it would be continuous until the playlist was cleared or SC7 restarted. Playing that song later under different circumstances would usually not cause reboots, but it could happen with another. http://forums.slimdevices.com/showthread.php?t=38675
Created attachment 2726 [details] Log file as requested Log file containing the start of the song, the moment of the restart, and a few seconds after playing resumes.
Eelcov: it looks like your player is disconnecting. Could it be a network issue? Or possibly a reboot as Jim suggests? What do you see on the screen when this happens?
It is not a reboot. Immediately after the music stops (and restarts) the display just shows the song name, not the startup sequence. A reboot takes several seconds and I would definitely have noticed that. A network problems seems unlikely. A flood ping shows a packet loss of less than 0.1% while the squeezebox plays flawlessly. Further information (if useful): all songs are stored as Apple Lossless, and converted via the ALAC utility from http://freshmeat.net/projects/alac/
Can somebody in QA follow up to try to reproduce?
Could this be an issue with the alac decoder? What version are you running? Perhaps player.source debug logging would help.
Ross: can you try to reproduce this on Fedora 7?
Created attachment 2821 [details] Log on player.* Logfile during a restart. Settings: player.source = Info player.streaming = Warn Alac is version 0.1.3 * http://freshmeat.net/projects/alac/ * http://craz.net/programs/itunes/alac.html
EeelcoV: Are you not using the alac that comes with SqueezeCenter?
I'll continue trying tomorrow, but I am still unable to reproduce this. I've had apple lossless files playing for 4 hours today with FC7, 6 hours yesterday with FC8, so far so good. I'm using the alac that comes with SC7. Dean OK with you if I reduce this to a normal bug and bump it to 7.0.1?
Ross: did you get anywhere with this on FC7?
No, I did not use SqueezeCenter's own alac. Didn't know it existed. I just removed my own version, and will see if that makes a positive difference. The restarts seem to happen less often with the most recent SqueezeCenter; I'm now using 17225, and update daily using yum.
Ross has been continuing to try to reproduce this.
Will continue for investigate for 7.0.1.
EelcoV, have you seen this since trying the bundled Alac?
I have not seen this problem in the past few days. I do not know whether it is because of the bundled alac, or because of the newer version of SC.
I'll keep trying, EelcoV please let us know if you manage to reproduce.
EelcoV I'm going to close this bug for now as I've tried to reproduce this and haven't seen anything. I take it you haven't reproduced it since using the bundled alac. If you have, or you see this again in the future, or anyone else does, please feel free to re-open.
(In reply to comment #20) > EelcoV I'm going to close this bug for now as I've tried to reproduce this and > haven't seen anything. I take it you haven't reproduced it since using the > bundled alac. If you have, or you see this again in the future, or anyone else > does, please feel free to re-open. > Marking bug as closed, if you see the issue appear again, please reopen the bug.