SqueezeBox Binding server disconnecting problem

LeeC77 · December 28, 2021, 6:29pm

First thanks fort the great binding, one of my most used

I have recently migrated from openHAB 3.1 to 3.2 (yesterday) and was just testing all was good when I ran into this issue.
When I use (operate) items linked to the media control or the next and previous channels of the Squeezebox binding, I lose control of all players; that is play, pause etc stop working and the status items no longer update: play time, duration, album details, cover art etc.

To recover I remove all squeezebox items and things, followed by reinstalling the things and all the items. Reconnection to LMS is re-established until I use the next/previous transport control again.
Tried to uninstall and reinstall the binding as I had just migrated OH3.1 -->3.2, log output:

Removing features: openhab-binding-squeezebox/[3.2.0,3.2.0]...
Adding features: openhab-binding-squeezebox/[3.2.0,3.2.0]...`

… this had no effect on the problem.
Also restarted LMS a couple of times and that made no difference either.
Control at the physical player, via the Squeeze App and through the LMS IP:9000 worked continuously.
The problem seems to be when I’m getting this debug from the squeezebox binding:
Debug gives me this periodically, after I try to use next/previous item.

  2021-12-28 17:00:00.900 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - no connection to squeeze server when trying to send command, returning...
  2021-12-28 17:00:42.243 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - no connection to squeeze server when trying to send command, returning...

And here is a cutting of the debug log at the point I pressed next " >>" on the player transport.

2021-12-28 17:15:15.198 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: favorites items 0 100

2021-12-28 17:15:22.182 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: players 0

2021-12-28 17:16:03.226 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:22:96:40 pause 1

2021-12-28 17:16:10.826 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:22:96:40 play

2021-12-28 17:16:22.186 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: players 0

2021-12-28 17:17:22.188 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: players 0

2021-12-28 17:17:43.233 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:22:96:40 pause 1

2021-12-28 17:17:45.706 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:22:96:40 play

2021-12-28 17:17:48.363 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - Sending command: 00:04:20:22:96:40 playlist index +1

2021-12-28 17:17:53.880 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - no connection to squeeze server when trying to send command, returning...

2021-12-28 17:18:00.673 [DEBUG] [rnal.handler.SqueezeBoxServerHandler] - no connection to squeeze server when trying to send command, returning...

May be related to the following post but the symptoms are different: https://community.openhab.org/t/oh3-squeezebox-binding-constantly-going-online-offline/129140

I have been running the squeezebox binding in OH2.X for two years without issue and I have made no changes to my LMS.
My bindings, things and items are all configured through files.

Help would be greatly appreciated.

My openHAB was setup via openhabian on a RasPi4 4GB:

##   Release = Raspbian GNU/Linux 10 (buster)
##    Kernel = Linux 5.10.63-v7l+
##  Platform = Raspberry Pi 4 Model B Rev 1.2
##    Uptime = 0 day(s). 23:58:26
## CPU Usage = 17.54% avg over 4 cpu(s) (4 core(s) x 1 socket(s))
##  CPU Load = 1m: 0.34, 5m: 0.40, 15m: 0.50
##    Memory = Free: 0.70GB (18%), Used: 3.09GB (82%), Total: 3.79GB
##      Swap = Free: 2.43GB (100%), Used: 0.00GB (0%), Total: 2.43GB
##      Root = Free: 22.45GB (80%), Used: 5.31GB (20%), Total: 28.98GB
##   Updates = 0 apt updates available.
##  Sessions = 1 session(s)
## Processes = 132 running processes of 32768 maximum processes

and OpenHAB runtimeInfo:

version: 3.2.0
  buildString: Release Build
locale: en-GB
systemInfo:
  configFolder: /etc/openhab
  userdataFolder: /var/lib/openhab
  logFolder: /var/log/openhab
  javaVersion: 11.0.13
  javaVendor: Azul Systems, Inc.
  javaVendorVersion: Zulu11.52+13-CA
  osName: Linux
  osVersion: 5.10.63-v7l+
  osArchitecture: arm
  availableProcessors: 4
  freeMemory: 32687816
  totalMemory: 324403200
bindings:
  - amazonechocontrol
  - astro
  - bluetooth
  - exec
  - gpstracker
  - harmonyhub
  - http
  - hue
  - neato
  - network
  - sonoff
  - squeezebox
  - wemo
  - zwave

mhilbush · December 28, 2021, 8:01pm

A very strange problem, indeed!

I don’t have very many things I can suggest for you to try. Here are a few that come to mind.

What happens if you restart the binding from the console (bundle:restart org.openhab.binding.squeezebox)? Is the connection to the LMS restored?
What happens when you restart OH? Is the connection to the LMS restored?
Are you certain there’s only one version of the binding active (list -s | grep squeezebox)

LeeC77 · December 28, 2021, 10:34pm

Thanks for the quick response, so I have tried the ideas you suggested, here is the status on each and some further findings.

Seems like there is only one binding:

openhab> list -s | grep squeezebox
343 │ Active │  80 │ 3.2.0                 │ org.openhab.binding.squeezebox
openhab>

The connection doesn’t restore, I have the DEBUG logs.

If you want the logs I can DM them

Update.
Looks like this might not be as related to every next previous item operation as I thought, I did manage to move the playing track forward and backwards in the playlist at least once and then perform a pause play before the connection failed.

It seems the only way to get the connection back, and it doesn’t always work, is to rename my Squeezebox.items file to …xitems and then comment out the Bridge squeezebox definition in the home.things file and save. Wait a short while and then reverse the process.

Could this be related to my use of config files, just noticed this ERROR on restoring my Squeezebox.items file:

2021-12-28 22:18:07.050 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'Squeezebox.items'

2021-12-28 22:18:07.269 [ERROR] [ore.common.registry.AbstractRegistry] - Cannot inform the listener "org.openhab.core.thing.internal.ChannelLinkNotifier@5f3e7f" about the "UPDATED" event: Value must be between 0 and 100

java.lang.IllegalArgumentException: Value must be between 0 and 100

	at org.openhab.core.library.types.PercentType.validateValue(PercentType.java:93) ~[?:?]

	at org.openhab.core.library.types.PercentType.<init>(PercentType.java:88) ~[?:?]

Think I need to look into that a bit more. See if its repeatable, find the cause?
I was updating the Alexa tagging in that .items file, but I have backed those out.

Any other suggestions welcome?

mhilbush · December 28, 2021, 10:46pm

It’s really odd that a restart of OH doesn’t resolve the connection issue. And I doubt the DEBUG logs will be helpful. But you might try TRACE level logging just to see if it reveals anything else. Especially when the binding starts after an OH restart.

You definitely should try to fix the cause of the IAE, although I doubt that’s the cause of the connection issues.

Did you try clearing tmp and cache to see if that makes a difference.

Also curious if the LMS is running on the same host as openHAB.

And, finally, by any chance are you running a Pi with an SD card? Sometimes these bizarre issues can be caused by an SD card that’s starting to fail.

I’m really just grasping at straws here.

LeeC77 · December 28, 2021, 11:24pm

Okay progress, I have resolved the cause of the IAE. This was it:

Dimmer SqueezeBoxTouchPlayListIndex "Touch Playlist index" (SqueezeboxTouch) {channel="squeezebox:squeezeboxplayer:lms:squeezeboxTouch:playListIndex"}

Wrong item type, corrected it to:
Number SqueezeBoxTouchPlayListIndex "Touch Playlist index" (SqueezeboxTouch) {channel="squeezebox:squeezeboxplayer:lms:squeezeboxTouch:playListIndex"}

On its own that only resolved the IAE error.

So I stopped openHAB service and cleaned the cache.

sudo systemctl stop openhab.service
sudo openhab-cli clean-cache

and on the restart of the openhab service the connection restored.
Quick test and the connection appears to be staying up.

I wonder how long that has been lurking there, and if the clean-cache would have fixed it on its own.
All my other squeezebox items definition appear correctly defined.

Thanks for your help just discussing it and steering the investigation helped me rule out possible causes quickly.
Perhaps this is a lesson in abandoning file configuration and moving to all GUI config.

mhilbush · December 28, 2021, 11:37pm

Glad you got it sorted out.

I’m guessing that the clean-cache is what resolved the issue. I’ve seen some pretty odd behavior when something is whacked up in the cache.

Nah. I’ve been doing file-based configuration ever since I started using openHAB back in 2016.