search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.86k stars 3.56k forks source link

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

Closed UdoWeberJR closed 5 years ago

UdoWeberJR commented 5 years ago

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)

wborn commented 5 years ago

Thanks for reporting the issue Udo. Can you create an issue for this in the Eclipse SmartHome project issue tracker instead? That's the repository where the Bose Soundtouch code is maintained.

UdoWeberJR commented 5 years ago

Sure, sorry, didn't realize that fact.

wborn commented 5 years ago

Thanks for creating https://github.com/eclipse/smarthome/issues/6714 !