[Bose SoundTouch Binding] Exceptions during start and stop, only volume channel working

[UdoWeberJR]

Hi,

when I start openHAB and also when I explizit start the stopped Bose SoundTouch Binding I see the same exception (see below) multiple times. As a result only the volume channel seems to get the current values of the powered on SoundTouch 300.

Also when I stop the binding via the karaf console I get a Warning "Couldn't stop Thread".

I attached a log file with level set to TRACE for Bose SoundTouch Binding, hope that helps.

Let me know if you need anything else.
Greets Udo

Bose Trace Log.txt

Logs

Starting (X-out mac and ip)

2018-12-21 20:11:25.278 [ERROR] [ome.core.thing.link.ThingLinkManager] - Exception occurred while informing handler: Blocking message pending 10000 for BLOCKING
java.lang.IllegalStateException: Blocking message pending 10000 for BLOCKING
	at org.eclipse.jetty.websocket.common.WebSocketRemoteEndpoint.lockMsg(WebSocketRemoteEndpoint.java:130) ~[?:?]
	at org.eclipse.jetty.websocket.common.WebSocketRemoteEndpoint.sendString(WebSocketRemoteEndpoint.java:386) ~[?:?]
	at org.eclipse.smarthome.binding.bosesoundtouch.internal.CommandExecutor.getInformations(CommandExecutor.java:123) ~[?:?]
	at org.eclipse.smarthome.binding.bosesoundtouch.handler.BoseSoundTouchHandler.handleCommand(BoseSoundTouchHandler.java:172) ~[?:?]
	at org.eclipse.smarthome.core.thing.binding.BaseThingHandler.channelLinked(BaseThingHandler.java:233) ~[?:?]
	at org.eclipse.smarthome.core.thing.link.ThingLinkManager.lambda$0(ThingLinkManager.java:300) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:?]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:?]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:?]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:?]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:?]
	at java.lang.Thread.run(Thread.java:748) [?:?]

Followed by some repeating item changes:

2018-12-21 20:11:25.831 [hingStatusInfoChangedEvent] - 'bosesoundtouch:300:9884E304XXXX' changed from UNINITIALIZED to INITIALIZING

2018-12-21 20:11:25.832 [hingStatusInfoChangedEvent] - 'bosesoundtouch:300:9884E304XXXX' changed from INITIALIZING to ONLINE

2018-12-21 20:11:25.835 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_Volume changed from NULL to 20

2018-12-21 20:11:25.837 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_RateEnabled changed from NULL to OFF

2018-12-21 20:11:25.854 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_SkipEnabled changed from NULL to OFF

2018-12-21 20:11:25.859 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_SkipPreviousEnabled changed from NULL to OFF

2018-12-21 20:11:25.868 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from NULL to 

2018-12-21 20:11:25.872 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_OperationMode changed from NULL to STANDBY

2018-12-21 20:11:25.875 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_Power changed from NULL to OFF

2018-12-21 20:11:25.920 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from  to NULL

2018-12-21 20:11:25.946 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from NULL to 

2018-12-21 20:11:26.022 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from  to NULL

2018-12-21 20:11:26.077 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from NULL to 

2018-12-21 20:11:26.221 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from  to NULL

2018-12-21 20:11:26.231 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from NULL to 

2018-12-21 20:11:26.305 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from  to NULL

2018-12-21 20:11:26.308 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from NULL to 

2018-12-21 20:11:26.317 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from  to NULL

2018-12-21 20:11:26.342 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from NULL to 

2018-12-21 20:11:26.348 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from  to NULL

2018-12-21 20:11:26.352 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from NULL to 

2018-12-21 20:11:26.358 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from  to NULL

2018-12-21 20:11:26.361 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from NULL to 

2018-12-21 20:11:26.364 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from  to NULL

2018-12-21 20:11:26.370 [vent.ItemStateChangedEvent] - Speaker_Bose_SoundTouch_300_nowPlayingItemName changed from NULL to 

Stopping the binding via karaf console

2018-12-21 20:19:21.410 [hingStatusInfoChangedEvent] - 'bosesoundtouch:300:9884E304XXXX' changed from ONLINE to UNINITIALIZED

==> /var/log/openhab2/openhab.log <==

2018-12-21 20:19:22.444 [WARN ] [e.jetty.util.thread.QueuedThreadPool] - QueuedThreadPool[WebSocketClient@9768421]@190b413{STOPPING,8<=8<=200,i=0,q=3}[org.eclipse.jetty.util.thread.TryExecutor$$Lambda$116/12917523@19a720d] Couldn't stop Thread[WebSocketClient@9768421-140,5,main]

==> /var/log/openhab2/events.log <==

2018-12-21 20:19:22.459 [hingStatusInfoChangedEvent] - 'bosesoundtouch:300:9884E304XXXX' changed from UNINITIALIZED to OFFLINE (COMMUNICATION_ERROR): Binding shutdown

2018-12-21 20:19:22.474 [hingStatusInfoChangedEvent] - 'bosesoundtouch:300:9884E304XXXX' changed from OFFLINE (COMMUNICATION_ERROR): Binding shutdown to UNINITIALIZED (HANDLER_MISSING_ERROR)

For completeness here my thing file:

Thing bosesoundtouch:300:9884E304XXXX "Bose SoundTouch 300" @ "Living room" [host="192.168.XXX.XX", macAddress="9884E304XXXX"]

Enviroment

Bose Software Version 20.0.6
Binding = BoseSoundTouch Binding 0.10.0.oh240
Raspbian GNU/Linux 9 (stretch)
Kernel = Linux 4.14.79-v7+
Platform = Raspberry Pi 3 Model B Rev 1.2
OpenHAB = openhab 2.4.0-1 (Release Build)