Openhab-addons: [yamaha] amplifier remain offline after openhab restart

Created on 21 Apr 2019  ·  15Comments  ·  Source: openhab/openhab-addons

description

My Yamaha receiver works as expected, when it is switched on during openhab restart. When the receiver is switched off, the receiver remains offline in openhab after an openhab restart.
A bundle restart solves this problem then.

At startup this messages are written to the log. After switching ON the yamaha amplifier nothing happens, till I restart the bundle. I fear this could be bug. Hope someone can have a look at it. Thanks.

2019-04-12 21:25:39.666 [INFO ] [el.core.internal.ModelRepositoryImpl] - Loading model 'yamaha.things'

2019-04-12 21:25:55.089 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at http://192.168.2.15:8080
2019-04-12 21:25:55.100 [INFO ] [.dashboard.internal.DashboardService] - Started Dashboard at https://192.168.2.15:8443
2019-04-12 21:25:57.655 [WARN ] [internal.handler.YamahaBridgeHandler] - Communication error. Please review your Yamaha thing configuration.
java.net.NoRouteToHostException: Keine Route zum Zielrechner (Host unreachable)
        at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:?]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[?:?]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[?:?]
        at java.net.Socket.connect(Socket.java:589) ~[?:?]
        at java.net.Socket.connect(Socket.java:538) ~[?:?]
        at sun.net.NetworkClient.doConnect(NetworkClient.java:180) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:463) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:558) ~[?:?]
        at sun.net.www.http.HttpClient.<init>(HttpClient.java:242) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:339) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:357) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1220) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1156) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1050) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:984) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1334) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1309) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLConnection.postMessage(XMLConnection.java:81) ~[247:org.openhab.binding.yamahareceiver:2.5.0.201904040140]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLConnection.sendReceive(XMLConnection.java:119) ~[247:org.openhab.binding.yamahareceiver:2.5.0.201904040140]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getResponse(XMLProtocolService.java:81) ~[247:org.openhab.binding.yamahareceiver:2.5.0.201904040140]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.DeviceInformationXML.update(DeviceInformationXML.java:91) ~[247:org.openhab.binding.yamahareceiver:2.5.0.201904040140]
        at org.openhab.binding.yamahareceiver.internal.handler.YamahaBridgeHandler.updateDeviceInformation(YamahaBridgeHandler.java:258) ~[247:org.openhab.binding.yamahareceiver:2.5.0.201904040140]
        at org.openhab.binding.yamahareceiver.internal.handler.YamahaBridgeHandler.connectionEstablished(YamahaBridgeHandler.java:345) [247:org.openhab.binding.yamahareceiver:2.5.0.201904040140]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolFactory.createConnection(XMLProtocolFactory.java:30) [247:org.openhab.binding.yamahareceiver:2.5.0.201904040140]
        at org.openhab.binding.yamahareceiver.internal.handler.YamahaBridgeHandler.initialize(YamahaBridgeHandler.java:325) [247:org.openhab.binding.yamahareceiver:2.5.0.201904040140]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [135:org.openhab.core:2.5.0.201904010543]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [135:org.openhab.core:2.5.0.201904010543]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        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) [?:?]
2019-04-12 21:25:59.386 [WARN ] [core.thing.internal.ThingManagerImpl] - Initializing handler for thing 'yamahareceiver:yamahaAV:receiverWZ' takes more than 5000ms.
2019-04-12 21:26:00.727 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.yamahareceiver.internal.handler.YamahaBridgeHandler@7347952a': Could not communicate with the device
java.lang.RuntimeException: Could not communicate with the device
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.InputConverterXML.<init>(InputConverterXML.java:62) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolFactory.InputConverter(XMLProtocolFactory.java:119) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.handler.YamahaBridgeHandler.initialize(YamahaBridgeHandler.java:326) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [135:org.openhab.core:2.5.0.201904010543]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [135:org.openhab.core:2.5.0.201904010543]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        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) [?:?]
Caused by: java.net.NoRouteToHostException: Keine Route zum Zielrechner (Host unreachable)
        at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:?]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[?:?]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[?:?]
        at java.net.Socket.connect(Socket.java:589) ~[?:?]
        at java.net.Socket.connect(Socket.java:538) ~[?:?]
        at sun.net.NetworkClient.doConnect(NetworkClient.java:180) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:463) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:558) ~[?:?]
        at sun.net.www.http.HttpClient.<init>(HttpClient.java:242) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:339) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:357) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1220) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1156) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1050) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:984) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1334) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1309) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLConnection.postMessage(XMLConnection.java:81) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLConnection.sendReceive(XMLConnection.java:119) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getResponse(XMLProtocolService.java:81) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getZoneResponse(XMLProtocolService.java:69) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getInputs(XMLProtocolService.java:101) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.InputConverterXML.createInputsWithoutMapping(InputConverterXML.java:100) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.InputConverterXML.<init>(InputConverterXML.java:59) ~[?:?]
        ... 12 more
2019-04-12 21:26:00.776 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'yamahareceiver:yamahaAV:receiverWZ': Could not communicate with the device
java.lang.RuntimeException: Could not communicate with the device
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.InputConverterXML.<init>(InputConverterXML.java:62) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolFactory.InputConverter(XMLProtocolFactory.java:119) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.handler.YamahaBridgeHandler.initialize(YamahaBridgeHandler.java:326) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [135:org.openhab.core:2.5.0.201904010543]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [135:org.openhab.core:2.5.0.201904010543]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        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) [?:?]
Caused by: java.net.NoRouteToHostException: Keine Route zum Zielrechner (Host unreachable)
        at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:?]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[?:?]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[?:?]
        at java.net.Socket.connect(Socket.java:589) ~[?:?]
        at java.net.Socket.connect(Socket.java:538) ~[?:?]
        at sun.net.NetworkClient.doConnect(NetworkClient.java:180) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:463) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:558) ~[?:?]
        at sun.net.www.http.HttpClient.<init>(HttpClient.java:242) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:339) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:357) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1220) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1156) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1050) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:984) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1334) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1309) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLConnection.postMessage(XMLConnection.java:81) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLConnection.sendReceive(XMLConnection.java:119) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getResponse(XMLProtocolService.java:81) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getZoneResponse(XMLProtocolService.java:69) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getInputs(XMLProtocolService.java:101) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.InputConverterXML.createInputsWithoutMapping(InputConverterXML.java:100) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.InputConverterXML.<init>(InputConverterXML.java:59) ~[?:?]
        ... 12 more

My thing definition:

Bridge yamahareceiver:yamahaAV:receiverWZ "Yamaha Receiver RX-V473" [host="192.168.x.yyy"] {
    Thing zone Main_Zone "Main Zone" @ "Wohnzimmer" [zone="Main_Zone", volumeDbMin=-81, volumeDbMax=12]
}

Expected Behavior

I would expect, that the binding discoveres automatically that the amplifier is switched on and initializes the thing.

Current Behavior

As explained above:
the amplifier stay offline, when it was switched off during openhab restart.

Possible Solution

As workaround: restart the yamaha binding

Steps to Reproduce (for Bugs)

  1. yamaha amplifier thing is online (e.g. in PaperUI)
  2. switch off the Yamaha amplifier
  3. restart openhab
  4. switch on yamaha amplifier
    3a. check: yamaha amplifier thing stays offline in openhab
  5. bundle:restart
    4a. check: yamaha amplifier thing is online (again) in openhab

Your Environment

openhab2 2.5.0~S1566-1
debian stretch

bug
Source
picture staehler

All 15 comments

This messages I get at openhab restart:

2019-04-24 10:25:41.731 [ERROR] [nal.common.AbstractInvocationHandler] - An error occurred while calling method 'ThingHandler.initialize()' on 'org.openhab.binding.yamahareceiver.internal.handler.YamahaBridgeHandler@1d5650ff': Could not communicate with the device
java.lang.RuntimeException: Could not communicate with the device
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.InputConverterXML.<init>(InputConverterXML.java:62) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolFactory.InputConverter(XMLProtocolFactory.java:119) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.handler.YamahaBridgeHandler.initialize(YamahaBridgeHandler.java:326) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [135:org.openhab.core:2.5.0.201904010543]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [135:org.openhab.core:2.5.0.201904010543]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        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) [?:?]
Caused by: java.net.NoRouteToHostException: Keine Route zum Zielrechner (Host unreachable)
        at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:?]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[?:?]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[?:?]
        at java.net.Socket.connect(Socket.java:589) ~[?:?]
        at java.net.Socket.connect(Socket.java:538) ~[?:?]
        at sun.net.NetworkClient.doConnect(NetworkClient.java:180) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:463) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:558) ~[?:?]
        at sun.net.www.http.HttpClient.<init>(HttpClient.java:242) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:339) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:357) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1220) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1156) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection$6.run(HttpURLConnection.java:1040) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection$6.run(HttpURLConnection.java:1038) ~[?:?]
        at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
        at java.security.AccessController.doPrivilegedWithCombiner(AccessController.java:782) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1037) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:984) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1334) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.access$100(HttpURLConnection.java:91) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection$8.run(HttpURLConnection.java:1301) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection$8.run(HttpURLConnection.java:1299) ~[?:?]
        at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
        at java.security.AccessController.doPrivilegedWithCombiner(AccessController.java:782) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1298) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLConnection.postMessage(XMLConnection.java:81) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLConnection.sendReceive(XMLConnection.java:119) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getResponse(XMLProtocolService.java:81) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getZoneResponse(XMLProtocolService.java:69) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getInputs(XMLProtocolService.java:101) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.InputConverterXML.createInputsWithoutMapping(InputConverterXML.java:100) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.InputConverterXML.<init>(InputConverterXML.java:59) ~[?:?]
        ... 12 more

==> /var/log/openhab2/events.log <==
2019-04-24 10:25:41.763 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:receiverWZ' changed from OFFLINE (COMMUNICATION_ERROR): Keine Route zum Zielrechner (Host unreachable) to UNINITIALIZED (HANDLER_INITIALIZING_ERROR): Could not communicate with the device

==> /var/log/openhab2/openhab.log <==
2019-04-24 10:25:41.761 [ERROR] [core.thing.internal.ThingManagerImpl] - Exception occurred while initializing handler of thing 'yamahareceiver:yamahaAV:receiverWZ': Could not communicate with the device
java.lang.RuntimeException: Could not communicate with the device
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.InputConverterXML.<init>(InputConverterXML.java:62) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolFactory.InputConverter(XMLProtocolFactory.java:119) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.handler.YamahaBridgeHandler.initialize(YamahaBridgeHandler.java:326) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:?]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:?]
        at org.eclipse.smarthome.core.internal.common.AbstractInvocationHandler.invokeDirect(AbstractInvocationHandler.java:153) [135:org.openhab.core:2.5.0.201904010543]
        at org.eclipse.smarthome.core.internal.common.Invocation.call(Invocation.java:53) [135:org.openhab.core:2.5.0.201904010543]
        at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:?]
        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) [?:?]
Caused by: java.net.NoRouteToHostException: Keine Route zum Zielrechner (Host unreachable)
        at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:?]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[?:?]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[?:?]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[?:?]
        at java.net.Socket.connect(Socket.java:589) ~[?:?]
        at java.net.Socket.connect(Socket.java:538) ~[?:?]
        at sun.net.NetworkClient.doConnect(NetworkClient.java:180) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:463) ~[?:?]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:558) ~[?:?]
        at sun.net.www.http.HttpClient.<init>(HttpClient.java:242) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:339) ~[?:?]
        at sun.net.www.http.HttpClient.New(HttpClient.java:357) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1220) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1156) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection$6.run(HttpURLConnection.java:1040) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection$6.run(HttpURLConnection.java:1038) ~[?:?]
        at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
        at java.security.AccessController.doPrivilegedWithCombiner(AccessController.java:782) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1037) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:984) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1334) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.access$100(HttpURLConnection.java:91) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection$8.run(HttpURLConnection.java:1301) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection$8.run(HttpURLConnection.java:1299) ~[?:?]
        at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
        at java.security.AccessController.doPrivilegedWithCombiner(AccessController.java:782) ~[?:?]
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1298) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLConnection.postMessage(XMLConnection.java:81) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLConnection.sendReceive(XMLConnection.java:119) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getResponse(XMLProtocolService.java:81) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getZoneResponse(XMLProtocolService.java:69) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getInputs(XMLProtocolService.java:101) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.InputConverterXML.createInputsWithoutMapping(InputConverterXML.java:100) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.InputConverterXML.<init>(InputConverterXML.java:59) ~[?:?]
        ... 12 more

The funny thing is, after starting my amplifier, openhab autodiscovers a new thing:

2019-04-24 10:32:49.584 [home.event.InboxAddedEvent] - Discovery Result with UID 'yamahareceiver:yamahaAV:5f9ec1b3_ed59_1900_4530_00a0de915864' has been added.
2019-04-24 10:32:49.583 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'yamahareceiver:yamahaAV:5f9ec1b3_ed59_1900_4530_00a0de915864' to inbox.

Is there nobody who can have a look at this?

staehler picture staehler on 24 Apr 2019

Just more info:
After the openhab reboot, I just reloaded the yamaha bundle, then immediately the right thing is online

2019-04-24 10:36:39.022 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:receiverWZ:Main_Zone' changed from OFFLINE (BRIDGE_OFFLINE) to UNINITIALIZED
2019-04-24 10:36:39.050 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:receiverWZ:Main_Zone' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2019-04-24 10:36:39.053 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:receiverWZ' changed from UNINITIALIZED (HANDLER_INITIALIZING_ERROR): Could not communicate with the device to UNINITIALIZED
2019-04-24 10:36:39.062 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:receiverWZ' changed from UNINITIALIZED to UNINITIALIZED (HANDLER_MISSING_ERROR)
2019-04-24 10:36:39.291 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:receiverWZ' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
2019-04-24 10:36:39.304 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:receiverWZ' changed from INITIALIZING to OFFLINE (CONFIGURATION_PENDING): Waiting for data
2019-04-24 10:36:39.326 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:receiverWZ:Main_Zone' changed from UNINITIALIZED (HANDLER_MISSING_ERROR) to INITIALIZING
2019-04-24 10:36:39.359 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:receiverWZ:Main_Zone' changed from INITIALIZING to OFFLINE (BRIDGE_OFFLINE)

==> /var/log/openhab2/openhab.log <==
2019-04-24 10:36:39.628 [INFO ] [al.protocol.xml.DeviceInformationXML] - Found zones: [Main_Zone], features: [AIRPLAY, USB, TUNER, NET_RADIO]

==> /var/log/openhab2/events.log <==
2019-04-24 10:36:39.635 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:yamahaAV:receiverWZ' has been updated.
2019-04-24 10:36:39.640 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:yamahaAV:receiverWZ' has been updated.

==> /var/log/openhab2/openhab.log <==
2019-04-24 10:36:39.667 [INFO ] [ternal.protocol.xml.SystemControlXML] - The party_mode channel is not supported on your model
2019-04-24 10:36:39.679 [INFO ] [ternal.protocol.xml.SystemControlXML] - The party_mode_mute channel is not supported on your model
2019-04-24 10:36:39.692 [INFO ] [ternal.protocol.xml.SystemControlXML] - The party_mode_volume channel is not supported on your model

==> /var/log/openhab2/events.log <==
2019-04-24 10:36:39.790 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:receiverWZ' changed from OFFLINE (CONFIGURATION_PENDING): Waiting for data to ONLINE
2019-04-24 10:36:39.872 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:receiverWZ:Main_Zone' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-04-24 10:36:39.946 [vent.ItemStateChangedEvent] - Yamaha_Power changed from NULL to ON
2019-04-24 10:36:39.959 [vent.ItemStateChangedEvent] - Yamaha_SurroundProgram changed from NULL to 5ch Stereo
2019-04-24 10:36:39.969 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:receiverWZ:Main_Zone' has been updated.
2019-04-24 10:36:39.973 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:receiverWZ:Main_Zone' has been updated.
2019-04-24 10:36:39.983 [vent.ItemStateChangedEvent] - Yamaha_Volume changed from NULL to 25
staehler picture staehler on 24 Apr 2019

Will this bug fixed in short time?
Otherwise I need to make some monitoring, which restarts the binding automatically. I cannot involve my wife to execute this workaround (reload binding), so it must happen automatically or - of cource much better - the binding handles this by itself.

staehler picture staehler on 11 Jun 2019

The problem still exists. Am I the onyl user who is suffering from this bug?
I always switch my electrical consumer powerless, so that my yamaha receiver is quite often offline, when I restart openhab. Than the receiver stays unconnected to openhab, till I restart the bundle ...

staehler picture staehler on 23 Jul 2019

Seems, that nobody is able to fix this problem, right?

What can I do to workaround this bug?

staehler picture staehler on 10 Aug 2019

Hi @staehler - its not that nobody can fix the bug, the problem is that the maintainers and Binding developers are all volunteers and unless they use the same hardware it makes it more challenging to fix or want to spend time on it.

The two code owners listed for the binding are @davidgraeff and @zarusz and David seems to be quite busy with other openHAB duties.

From looking at the exceptions the NoRouteToHostException probably isn't being handled gracefully and because it occurs in the initialize() function the Thing doesn't let openHAB know that it initialized correctly and due to this openHAB skips loading the Thing. If it can handle that situation more gracefully it'll likely work as expected.

Cossey picture Cossey on 19 Aug 2019

Hi,

I can look into this but not in the next 2 weeks.

I am still on OH 2.4.0 snapshot and would have to upgrade my home setup to retest this. Not sure about the OH current bugfix process mainly if the fix would be a 2.5.x release or 2.6.0-snapshot and then 2.6.0 (which means longer waiting for you).

BTW I am not in any way related to OH nor have I any other OH duties as stated above. I am just a user as you guys are that happened to know how to program ;) I haven't had time to be up to date with recent OH releases and topics.

Cheers

zarusz picture zarusz on 19 Aug 2019

Hey @zarusz sorry I should've been more clear, I was talking about davidgraeff re: openHAB duties. I did take a look at the Binding code but I needed a few more rounds, there's quite a few abstraction layers to that Binding which makes it a bit more involved when it comes to determining what the code does (I got lost a few times). I might try and take a crack at it, it's just a matter of trying to handle that exception in initialisation. I think it's after the connection object is created and send it's first request to the receiver.

Cossey picture Cossey on 19 Aug 2019
👍1

The binding experienced a lot of code rot. The manual xml parsing is very 90ties and I guess the binding would be only half the size if modernized. I do not have a Yamaha receiver anymore, so cannot help here.

davidgraeff picture davidgraeff on 19 Aug 2019

Hey @zarusz you wouldn't need to update your home setup to develop and test this Binding, it is still possible to test 2.5.0 snapshot Bindings on older versions - as long as you don't use features from 2.5 (which this doesn't use). Its just a matter of dropping the compiled file into your openHAB add-ons folder (once you have removed the older Yamaha Binding from the Add-ons section).

Do you want to try and have a look at this problem? If you like I can assign this issue to you, even if you cannot look at it for a while yet. Taking a look at this bug when you have a moment would be awesome. I would love to help but I don't have one of these receivers.

Cossey picture Cossey on 21 Aug 2019

@Cossey yes, please assign to me. I will look once I get some free time. Cheers.

zarusz picture zarusz on 21 Aug 2019

Thanks a lot guys for your effort. I really appreciate it.

Am 21. August 2019 11:33:39 schrieb Tomasz Maruszak notifications@github.com:

@Cossey yes, please assign to me. I will look once I get some free time.
Cheers.
—
You are receiving this because you were mentioned.
Reply to this email directly, view it on GitHub, or mute the thread.

staehler picture staehler on 21 Aug 2019

I've made the necessary changes to the Yamaha Receiver and tested two scenarios:

  • Unplugged my Yamaha device from network and started OpenHAB, then plugged back after some time.
  • On a running OpenHAB I've unplugged my Yamaha device from network, waited, plugged back in.

In both cases the binding has gone into OFFLINE and after connectivity was restored back to ONLINE.
My OH is 2.4.0-SNAPSHOT, binding was built against 2.5.0-SNAPSHOT.

Anyone interested (incl. @staehler) please give it a try. You should only need to:
1) uninstall the stock Yamaha binding,
2) add my custom built JAR.

Once the fix is also confirmed by other users I will issue a pull request.

zarusz picture zarusz on 6 Oct 2019

Choice! Thanks @zarusz for making this binding more stable. Hopefully others can test and give feedback.

Cossey picture Cossey on 6 Oct 2019

@zarusz
I've installed your binding

bundle:list -s | grep -i yamaha
285 x Active   x  80 x 2.5.0.201910052153    x org.openhab.binding.yamahareceiver

and tested following szenario, which didn't work till now:

  1. plug off yamaha from power (not network)
  2. stop openhab and start it again
  3. power on yamaha
    At this point, the binding didn't recognize the yamaha device and it stayed offline.

I tried this szenario twice and both times it recognized the yamaha device. So I would say, you did an absolut great job 👍 

2019-10-06 10:28:28.881 [vent.ItemStateChangedEvent] - yamaha changed from OFF to ON
2019-10-06 10:28:29.459 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:yamahaAV:receiverWZ' has been updated.
2019-10-06 10:28:29.499 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:yamahaAV:receiverWZ' has been updated.
2019-10-06 10:28:29.620 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:receiverWZ' changed from OFFLINE (COMMUNICATION_ERROR): connect timed out to ONLINE
2019-10-06 10:28:29.761 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:receiverWZ:Main_Zone' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE
2019-10-06 10:28:31.361 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:receiverWZ:Main_Zone' has been updated.

I'm so happy that this is working now. Thank you so much!!

Hope your fix will be added to the official repository very soon.

staehler picture staehler on 6 Oct 2019
👍1
Was this page helpful?
0 / 5 - 0 ratings

Related issues

Alex5719 picture Alex5719  ·  6Comments
LukasA83 picture LukasA83  ·  5Comments
gk4 picture gk4  ·  3Comments
d3rh3ld picture d3rh3ld  ·  4Comments
tobiwan88 picture tobiwan88  ·  4Comments