Bugzilla – Bug 9565
Frequent disconnects with "new streaming" and flac files
Last modified: 2009-07-31 10:30:15 UTC
Wireless to squeezebox boom. SC version is 23224 running on Windows XP, sp3. Songs frequently stop playing. Often the Boom display goes completely blank. Sometimes it just goes to the "large" clock which is the power off screensaver. Usually pressing play on the remote or controller will restart the track over from the beginning. Sometimes it will stop again at essentially the same spot. Even more than once. If that happens then skipping the track to the next track, waiting a few seconds, and then going back to the problem track will allow it to play just fine. Again, several times witout error. Attached is a log file with "info" turned on per request from forum thread. The song that had the problem this time was Infidel by Five for Fighting.
Created attachment 4044 [details] log file
The player shouldn't be sync'd - according to the web UI but the log file does mention a "sync group". Not sure if it is a clue or not...
Doug: does the same thing happen with 7.2.1?
I've never run 7.2.1. I was running boom beta 7.2 and it was working fine. New Streaming was added to 7.2 boom beta and this problem occurred. Shortly after that New Streaming was removed for 7.2 beta. Problem went away. GA version of 7.2 did not have this issue, either. Moved up to 7.3 beta with new streaming and problem starts up again. No changes in hardware or systems other than the SC upgrade. Same physical location for the boom player. Wireless hub has not been moved. Wireless strength is reported by the boom to be around 70+ percent. Generally between 70 and 80 percent. I've watched it for about 5 minutes and in that time it hasn't shown a strength below 68%. Once it "reset" while I was watching the strength info and it read 75% - afterwords approx. the same: 76%. No remote activity, no controller activity, no microwave activity. The controller, located about 5 feet further away from the hub than the player, didn't appear to loose connection. Nearest neighbor's house is approx. 150 feet away - although this logged event occurred when they could have been using a microwave (7pm) it has also happened quite often much later when this would be unlikely. Any other logging that I should turn on?
Doug, it is clear from the log that at 19:16:20.0288 you had some sort of network problem. The connections to several players were lost at this time and it took some time for them to be reestablished. This looks like the root of the problem. There are only two possible incoming event types that could cause the disconnections but we would need slimproto=debug to determine just which it was. What is your wireless access-point type and firmware revision? After the reconnections, it is clear that the continue-to-play mechanism failed to work: bug 9446.
I've just checked in change 23274 for bug 9446. This should make the reconnect work again. I'd be pleased with some feedback.
My access point is a Belkin pre-n from several years ago, not the recent draft versions. Model F5D8230-4. It's been a year since I checked for firmware updates (this model seems to have been orphaned) but checking the belkin website now they have a couple of firmware updates from about a year ago that I might not have installed. Probably have, though, because I remember applying an update and there are only 2 versions out there and they have suspiciously close dates... Interesting that my laptop can maintain a continuous VPN connection without a problem - I always thought that if the connection dropped for a instant that it would break VPN connections. I will certainly be able check out the reconnect work - I'm thinking that it will be in tomorrow's nightly build? One thing that doesn't seem to fit the scenario of it being a network issue is that a song will stop IN THE SAME PLACE over and over again (I'd done it up to 6 times in a row). However, if you advance a track to another song and then go back to the original song it will play without issue. Both the same location and the workaround would seem to lend themselves to something other than a network hardware issue, right?
Yes, it will be in tomorrow's nightly build. I hear what you say about it being a network issue. The fact remains that several players disconnect almost simultaneously and seem to have a problem reconnecting. The fact that you can reproduce it at the same place each time in a particular track (unless you play another track first) is certainly interesting. Does it fail when you start playing with that track, or only when that track follows on from playing the previous track (without user intervention).
The scenario is that several songs are played. Then 1 has the issue. Restarting that song often (not always) results in it stopping at exactly the same spot over and over again. After restarting playing the track but before it hits the "bad spot" if you hit track advance and listen to a few seconds of that track and then track previous twice to go back to the issue track the issue track will play fine. Different tracks are the issue track each time. Tracks that have caused issues in past runs do not cause issues in current runs, etc. I did see the controller lock up when restarting the issue track last night. First time that has happened, though. Just seems to be really oddly repeatable to be a network firmware issue unless it has to do with something like a particular "kind" of packet or packet sets going back and forth somehow. Why I keep mentioning it.
I downloaded last night nightly and played music for about an hour and I didn't notice and music playing anomolies. There "should" have been at least 1 instance of the problem in the prior versions in that amount of time. Not a 100% test yet, but the best I could do before going to work this morning, and it looks very good so far. This seems to be masking the problem quite well. THANKS!! One note/observation. You mentioned "several players". I have 2 booms that are connected wirelesly. I also have one controller. Those are the only wireless devices that are connected up to SC. I have 3 other SB3s that are connected up in wired mode. Were they reporting disconnects? If so, then it cannot be my wireless network. I guess it could be my wired network but doesn't that seem unlikely? Nothing else is reporting drops or any sort of disconnect (even on my wireless network). With the auto-reconnect working this may drop way down on the list of things to do, but I can't help thinking that there is some sort of underlaying SC issue here somewhere.
The 'other' player for which a disconnect was reported at the same time was also a Boom (00:04:20:1e:00:59). See your log at 19:16:20. In fact, it lost its connection a second or so earlier than 00:04:20:1e:01:fb. I was mistaken when I said several: it was only two clients which disconnected. 00:04:20:1e:01:fb struggled to reconnect.
Alan if this bug turns out to have bits that you aren't the right person to work on, please tag it with the bug_meeting keyword and we can figure out who needs to work on the other parts.
Doug, is it still working ok? Do you think you could check your logs and see if it just keeps working or if the reconnect fixes are being used? You will need player.source=info and/or network.protocol.slimproto=info to see the reconnects. Alan.
I am figuring that the disconnects are still happenning but with the reconnect logic functioning it essentially isn't easily noticable anymore. I can do that. What should I search for in the logs to know that it is still disconnecting/reconnecting?
Look for "slimproto_close" and "Squeezebox says hello: " combinations. In particular look for the 'reconnect' element of the Hello message being non-zero or a non-zero value of bytes_received in "Squeezebox also says: bytes_received".
Well, I wasn't home to play anything for several days so the log file got huge with the info settings on. However, no disconnect/hellos at all. I've also played a boom wireless with a sb3, wired, synch'd to it for several hours without any hellos either. I'll try moving the boom to a different location and playing it some more. FYI the "other" boom has also been plugged into power the entire time as well - in the same location.
Created attachment 4107 [details] error log from disconnect
Created attachment 4108 [details] error log from disconnect
Just got a recreation. I moved the playing boom outside a bit furhter away from the wireless hub. The second boom was unmoved. Pausing didn't help. Only moving off of the track and then back on to it allowed it to play correctly. sorry, looks like I uploaded the log twice.
Doug, That log shows that you were playing (on player 00:04:20:1e:01:fb) John Mayer/Continuum/11-In Repair-Continuum.flac. At 16:51:35.5320 this had got to 183.8s of elapsed time. The 1s updates stopped at that time. 10s later, at 16:51:45.0057, player 00:04:20:1e:00:59 is logged as having disconnected. It reconnected at 16:51:54.2419. At 16:51:54.2709, player 00:04:20:1e:01:fb (the one that was playing) reconnects. The reconnects seems to go smoothly and streaming is restarted at byte offset 25576824 into the stream. At 16:51:54.8061 it reports an elapsed time of 202.6s, which just about corresponds. This track then plays to completion, after which Ricky Martin/03-She's All I Ever Had-Ricky Martin.flac starts playing. This is paused and unpaused a couple of times, before skipping to the next track. When did it "break" for you - during the middle of In Repair-Continuum or only when She's All I Ever Had-Ricky Martin started?
I should have described in more detail, sorry. I was thinking that the log would show it. The Ricky Martin song just playing choppy, broken pieces of sound from the bery beginning of the track. It wasn't quite the same as before when it fully stopped, but I figured the reconnect change was doing something there. Pausing and unpausing had no effect - silence and then choppy pieces. Again, only jumping to the next track and then back again allowed it to play fine.
It looks like the output-buffer underrun events are not happening, and the player never gets its buffers full enough. This is bug 9517.
Doug, please test when SB firmware 117 becomes available. I'm not sure when this will be right now.
Doug, fw 117 is out now.
That was great timing. I'd just gotten back from being on the road for about 2 weeks. I upgraded and ran for about 12 hours yesterday and 8 the day before without encountering any noticable issues. However, since the weather has changed here in Minnesota I was no longer out on my deck. I seemed to get the issue more out there than in the house. Seems like this is resolved.
This bug has been fixed in the 7.3.0 release version of SqueezeCenter! Please download the new version from http://www.slimdevices.com/su_downloads.html if you haven't already. If you are still experiencing this problem, feel free to reopen the bug with your new comments and we'll have another look.
Reduce number of active targets for SC