Bugzilla – Bug 9676
players falling way out of sync
Last modified: 2009-09-29 04:40:09 UTC
Tom and I have been syncing our respective players here at Logitech Minnesota for the past few weeks. It's been working quite well. Today the sync is lousy...sometimes the UIs (all UIs, not just controller) don't update with the new track info, sometimes the stream cuts out briefly, and right now we're way off sync (which for this particular track makes it sound like a round, which is kind of nice, but not intended). So, the question is, anything change in sync recently that might have exposed this problem? (SC 7.3 trunk, Linux, svn updated to Oct 7) Wireless signal strength of two players: Boom 96, SB3 68 I set player.sync to debug and captured this output during an event where the players got way out of sync. FWIW, this happened near a track boundary, and has happened several times today in similar locations. [08-10-08 10:50:04.7542] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223480864.976, 00:04:20:07:92:f2: +2 [08-10-08 10:50:05.7542] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223480864.976, 00:04:20:07:92:f2: +2 [08-10-08 10:50:06.7546] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223480864.976, 00:04:20:07:92:f2: +2 [08-10-08 10:50:07.7542] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223480864.976, 00:04:20:07:92:f2: +2 [08-10-08 10:50:08.4040] Slim::Player::Player::trackJiffiesEpoch (954) 00:04:20:1e:01:9d adjust jiffies epoch +0.004s [08-10-08 10:50:08.4103] Slim::Player::Squeezebox2::startAt (956) 00:04:20:1e:01:9d startAt: 664976255 [08-10-08 10:50:08.4112] Slim::Player::Squeezebox2::startAt (956) 00:04:20:07:92:f2 startAt: 663452885 [08-10-08 10:50:08.4474] Slim::Player::Player::trackJiffiesEpoch (954) 00:04:20:07:92:f2 adjust jiffies epoch +0.002s [08-10-08 10:50:08.5472] Slim::Player::Player::trackJiffiesEpoch (930) 00:04:20:1e:01:9d adjust jiffies epoch -0.003s [08-10-08 10:50:08.7578] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223481008.547, 00:04:20:07:92:f2: -143565 [08-10-08 10:50:09.7548] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223481008.546, 00:04:20:07:92:f2: -143565 [08-10-08 10:50:10.7847] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223481008.546, 00:04:20:07:92:f2: -143565 [08-10-08 10:50:11.4639] Slim::Player::Player::trackJiffiesEpoch (930) 00:04:20:07:92:f2 adjust jiffies epoch -0.001s [08-10-08 10:50:11.7548] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223481008.545, 00:04:20:07:92:f2: -143565 [08-10-08 10:50:12.7544] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223481008.546, 00:04:20:07:92:f2: -143566 [08-10-08 10:50:13.7546] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223481008.546, 00:04:20:07:92:f2: -143566 [08-10-08 10:50:14.0101] Slim::Player::Player::trackJiffiesEpoch (954) 00:04:20:10:05:7d adjust jiffies epoch +0.002s [08-10-08 10:50:14.7542] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223481008.546, 00:04:20:07:92:f2: -143565 [08-10-08 10:50:15.7543] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223481008.546, 00:04:20:07:92:f2: -143566 [08-10-08 10:50:16.7542] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223481008.546, 00:04:20:07:92:f2: -143565 [08-10-08 10:50:17.7546] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223481008.546, 00:04:20:07:92:f2: -143565 [08-10-08 10:50:18.7542] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223481008.546, 00:04:20:07:92:f2: +9712 [08-10-08 10:50:18.7550] Slim::Player::StreamingController::_CheckSync (486) 00:04:20:07:92:f2 resync: skipAhead 9712ms [08-10-08 10:50:20.7553] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223481008.546, 00:04:20:07:92:f2: +0 [08-10-08 10:50:21.7547] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223481008.546, 00:04:20:07:92:f2: +0 [08-10-08 10:50:22.7546] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223481008.546, 00:04:20:07:92:f2: +0 [08-10-08 10:50:23.7542] Slim::Player::StreamingController::_CheckSync (453) playPoints: 00:04:20:1e:01:9d: 1223481008.546, 00:04:20:07:92:f2: +0 [08-10-08 10:50:24.7546] Slim::Player::Str
Ben, if you can reproduce it please add player.source=info and network.protocol.slimproto=debug to the player.sync=debug logging. The numbers in your log output look very odd. It also seems odd that we see the pair of 'startAt' messages, as these should only happen on the first track, not at subsequent track changes.
Alan needs more debug from me if I can reproduce, so I'll assign this in my court to monitor. FYI, I've not seen this behavior since the day I reported it...
I have not been able to reproduce this. Moving to monitor...
Created attachment 4227 [details] server log from reproduction of sync issue bad sync behavior seen today on an updated Nov 10 svn 7.3 SC. turned on all the logging flags you indicated, Alan. Attached are the bottom 10,000 lines from the log (I have the rest of the log saved off if you want it). Behavior when I finally killed SC was the audio cutting out, lots of rebuffering messages, and the two synced players never fully recovering. Both players are on a WEP-encrypted wifi that should be very strong in signal.
I need to see the rest of the log to try and work out how your players got into this state. Can you compress and attach it please. In the end I think that you are suffering from the extreme effects of bug 7918.
Created attachment 4230 [details] tarball of entire log in case it's useful here's the entire log
I'm duping this to bug 14352 as that is the current bug tracking this problem. *** This bug has been marked as a duplicate of bug 14352 ***