OH2 snapshot, Squeezebox binding: no connection to squeeze server

Since I upgraded my OH2 snapshot end of December (now on #1179) and the LMS version also available at that time, I have found that OH2 looses the ability to control and read status from LMS after a few hours up-time.

Since I did the cardinal sin of upgrading them both at the same time, I now have a difficult time deciding where the fault is.

What I can see from the logs when the fault occur is:

2018-01-13 21:23:10.861 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - no connection to squeeze server when trying to send command, returning...
2018-01-13 21:23:34.980 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - no connection to squeeze server when trying to send command, returning...

OH2 event log then continuously logs currentPlayingTime fra ALL players, even though they are all paused:
(timestamps don’t match, but was the same.)

2018-01-13 21:57:07.194 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_0326298C_2279_4B11_A38D_30E70B6972CE_0004201ed6e0_currentPlayingTime changed from 359 to 360
2018-01-13 21:57:07.195 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_0326298C_2279_4B11_A38D_30E70B6972CE_0004202269ed_currentPlayingTime changed from 359 to 360
2018-01-13 21:57:08.195 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_0326298C_2279_4B11_A38D_30E70B6972CE_0004201ed6e0_currentPlayingTime changed from 360 to 361
2018-01-13 21:57:08.196 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_0326298C_2279_4B11_A38D_30E70B6972CE_0004202269ed_currentPlayingTime changed from 360 to 361
2018-01-13 21:57:09.201 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_0326298C_2279_4B11_A38D_30E70B6972CE_0004201ed6e0_currentPlayingTime changed from 361 to 362
2018-01-13 21:57:09.206 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_0326298C_2279_4B11_A38D_30E70B6972CE_0004202269ed_currentPlayingTime changed from 361 to 362
2018-01-13 21:57:09.206 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_0326298C_2279_4B11_A38D_30E70B6972CE_0004202269ed_currentPlayingTime changed from 362 to 363
2018-01-13 21:57:09.214 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_0326298C_2279_4B11_A38D_30E70B6972CE_0004201ed6e0_currentPlayingTime changed from 362 to 363
2018-01-13 21:57:11.196 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_0326298C_2279_4B11_A38D_30E70B6972CE_0004202269ed_currentPlayingTime changed from 363 to 364
2018-01-13 21:57:11.198 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_0326298C_2279_4B11_A38D_30E70B6972CE_0004201ed6e0_currentPlayingTime changed from 363 to 364
2018-01-13 21:57:12.196 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_0326298C_2279_4B11_A38D_30E70B6972CE_0004201ed6e0_currentPlayingTime changed from 364 to 365
2018-01-13 21:57:12.197 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_0326298C_2279_4B11_A38D_30E70B6972CE_0004202269ed_currentPlayingTime changed from 364 to 365
2018-01-13 21:57:13.197 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_0326298C_2279_4B11_A38D_30E70B6972CE_0004202269ed_currentPlayingTime changed from 365 to 366
2018-01-13 21:57:13.198 [vent.ItemStateChangedEvent] - squeezebox_squeezeboxplayer_0326298C_2279_4B11_A38D_30E70B6972CE_0004201ed6e0_currentPlayingTime changed from 365 to 366

Restarting Linux, OH2, Squeezebox-binding or LMS-server fixes the problem for a while.
All works fine from the LMS:9000 WEB interface.

Anyone else noticed this strange behavior?

Update:

  • just changing the ‘IP or Host name’ for LMS in Paper UI from LAN address to 127.0.0.1 or back fixes the problem for a while.
  • unlinked all ‘currentPlayingTime’ channels, just to see if these rapid event updates killed the binding … jury’s still out …

What is the thing status as shown in Paper UI? Is the squeezebox server ONLINE or OFFLINE? If OFFLINE, is it showing a detailed status message?

Did you upgrade end of December of early January? The reason I ask is that there was a problem introduced at the beginning of January that might possibly cause this. The problem occurs if you change the volume using the volume control in the LMS.

Thanks for replying.

Thing status is always Online.
I have apt-get up-dated/graded almost daily since the trouble started, hoping for it to be fixed :slight_smile:
As I could see from the logs, currentPlayingTime was constantly received from all players, but the periodic ‘Sending command: player 0’ logged an: 'no connection to squeeze server when trying to send command, returning…'
Same for any commands sendt from OH2 (rules and sitemap)
LMS WEB always work.

I have now unlinked currentPlayingTime & CoverArt (as it was trying to download .pngs from 3xBooms)
Connection fail time varies from 30min to 12hrs after OH2/binding restart.
Still up after I unlinked currentPlayingTime, but too early to conclude.
My .items/.rules was not changed when the connection trouble started. Have been working fine since I started using the binding in April-17

Also tried changing Volume From LMS WEB interface several times, but it doesn’t seem to break anything.

@OMR Sorry if I wasn’t clear about this.

There’s a bug in the squeezebox binding since January 1 that causes the behavior you’re seeing. If you change the volume of a player outside the binding (e.g. from the LMS web interface), the binding fails in a way that the connection to Squeezebox server drops, and cannot be reestablished until the binding is restarted.

You can verify this is the problem easily

  • put the binding in debug mode
  • restart the binding
  • change the player volume on the LMS web interface (by incrementing or decrementing)
  • send any command to a player (e.g. play, pause, etc.)
  • you should see an error like this in the log
2018-01-15 07:19:03.752 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - no connection to squeeze server when trying to send command, returning...
2018-01-15 07:20:03.752 [DEBUG] [ebox.handler.SqueezeBoxServerHandler] - no connection to squeeze server when trying to send command, returning...

Since I unlinked currentPlayingTime I have not been able to reproduce the bug.
Changing volume in LMS or locally on the player(s) and they still work from OH2 afterwards.

Anyway, this is a workaround.
Will a fix be announced when ready or should I just check GitHub?
No issue there yet.

Cheers

Sorry, but I’m still trying to understand the issue. I don’t see anything in the code that would suggest unlinking the currentPlayingTime channel could cause the behavior you’re seeing.

Can you post the version of the squeezebox binding and LMS you’re running?

Certainly:

2.3.0-SNAPSHOT Build #1179   
openhab> bundle:list | grep -i sq
212 | Active    |  80 | 2.3.0.201801130942     | SqueezeBox Binding

Logitech Media Server Version: 7.9.1 - 1515659378 @ Thu Jan 11 09:26:58 UTC 2018

Maybe it has to do with the overall network traffic the binding is receiving?

The currentPlayingTime events have been there for a very long time. And nothing else has changed in the binding that would’ve materially changed the network traffic received by the binding.

The only change to the binding that correlates to the timeframe of your issue is this change.

And it’s this line of code specifically that is known to cause the behavior you’re seeing. The code doesn’t properly handle + and - volume changes, causing the binding to fail silently (other than the debug message that’s logged whenever a command is sent to the LMS).

Strange things are afoot …

The only thing that triggered my attention to currentPlayingTime was the fact that the event.log was full of them (from all players even though nothing was playing) as long as the binding was in the failed state. That was what prompted me to unlink.

Are you still able to reproduce the error?
I’m not, but I had a 3 hrs power outage 12hrs ago and had to restart OH2 a few times when back from work to get my Z-wave stick up and running again, so my mileage is not so high yet.

The only way I can cause that error is to increment or decrement the volume in the LMS web interface. That causes parseInt to throw a NumberFormatException, which is not handled in the binding, thereby causing the Listener thread to exit silently. Once that happens, the binding will never reconnect to the LMS.

There’s a PR in the pipeline to fix the NumberFormatException.

You may be experiencing another error that causes the same symptom. But I can’t reproduce that.

@OMR The latest openHAB snapshot contains a fix to the above mentioned problem. If you try that version your problem still exists, we’ll need to further troubleshoot.

Nice. I will install it now.
Will report back in a day or two …

Day 1 - still going …
Day 3 - still OK, have adjusted volume both in LMS WEB and on players.

Conclusion: binding is back to its former glory :slight_smile:

Thanks a lot!