Yamaha Receiver Binding - connect timed out

Hello guys,

I´m using openhab 2.5M4 in docker on ubuntu 18.04 server and a Yamaha RX-V479. Every now and then I notice a connect timed out. When I used openhabian on a raspberry pi, everything went fine (for months).

Here are my files and my log:

yamaha.things:

Bridge yamahareceiver:yamahaAV:9ab0c000_f668_11de_9976_00a0ded43a90 "Yamaha Receiver RX-V479" [host="192.168.178.21", refreshInterval=60] {
    Thing zone Main_Zone "Yamaha RX-V479 Main_Zone" @ "location" [zone="Main_Zone"]
}

yamaha.items:

Switch      Yamaha_Power           "Yamaha Power [%s]"                <switch>             { channel="yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0ded43a90:Main_Zone:zone_channels#power" }
Dimmer      Yamaha_Volume          "Yamaha Volume [%.1f %%]"          <soundvolume>        { channel="yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0ded43a90:Main_Zone:zone_channels#volume" }
Switch      Yamaha_Mute            "Yamaha Mute [%s]"                 <soundvolume_mute>   { channel="yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0ded43a90:Main_Zone:zone_channels#mute" }

logfile:

2019-10-26 11:32:17.071 [TRACE] [internal.handler.YamahaBridgeHandler] - updateAllZoneInformation

2019-10-26 11:32:17.072 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.178.21:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><System><Power_Control><Power>GetParam</Power></Power_Control></System></YAMAHA_AV>

2019-10-26 11:32:17.081 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response

2019-10-26 11:32:17.083 [DEBUG] [ternal.protocol.xml.SystemControlXML] - System state - power: true, partyMode: false

2019-10-26 11:32:17.084 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.178.21:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Input><Input_Sel_Item>GetParam</Input_Sel_Item></Input></Main_Zone></YAMAHA_AV>

2019-10-26 11:32:17.084 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.178.21:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>

==> /openhab/userdata/logs/events.log <==

2019-10-26 11:32:17.092 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0ded43a90:Main_Zone' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR): connect timed out

==> /openhab/userdata/logs/openhab.log <==

2019-10-26 11:32:17.097 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response

2019-10-26 11:32:17.102 [TRACE] [rnal.protocol.xml.XMLProtocolService] - Zone Main_Zone - inputs: Spotify:RW, JUKE:RW, AirPlay:RW, MusicCast Link:RW, SERVER:RW, NET RADIO:RW, Bluetooth:R, USB:R, iPod (USB):R, TUNER:R, HDMI1:R, HDMI2:RW, HDMI3:R, HDMI4:R, HDMI5:R, HDMI6:R, AV1:R, AV2:R, AV3:R, AV4:R, AUDIO1:R, AUDIO2:RW, AUX:R

2019-10-26 11:32:17.102 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name Spotify to Spotify - as per no conversion rule

2019-10-26 11:32:17.103 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name JUKE to JUKE - as per legacy mapping

2019-10-26 11:32:17.103 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AirPlay to AIRPLAY - as per legacy mapping

2019-10-26 11:32:17.104 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name MusicCast Link to MusicCast Link - as per no conversion rule

2019-10-26 11:32:17.104 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name SERVER to SERVER - as per legacy mapping

2019-10-26 11:32:17.105 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name NET RADIO to NET RADIO - as per no conversion rule

2019-10-26 11:32:17.105 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name HDMI2 to HDMI2 - as per no conversion rule

2019-10-26 11:32:17.105 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AUDIO2 to AUDIO2 - as per no conversion rule

2019-10-26 11:32:17.105 [TRACE] [.protocol.xml.ZoneAvailableInputsXML] - Zone Main_Zone - available inputs: AIRPLAY, AUDIO2, HDMI2, JUKE, MusicCast Link, NET RADIO, SERVER, Spotify

==> /openhab/userdata/logs/events.log <==

2019-10-26 11:32:17.106 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0ded43a90:Main_Zone' has been updated.

and later on:

2019-10-26 11:38:17.084 [TRACE] [internal.handler.YamahaBridgeHandler] - updateAllZoneInformation

2019-10-26 11:38:17.085 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.178.21:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><System><Power_Control><Power>GetParam</Power></Power_Control></System></YAMAHA_AV>

2019-10-26 11:38:17.100 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response

2019-10-26 11:38:17.102 [DEBUG] [ternal.protocol.xml.SystemControlXML] - System state - power: true, partyMode: false

2019-10-26 11:38:17.103 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.178.21:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Input><Input_Sel_Item>GetParam</Input_Sel_Item></Input></Main_Zone></YAMAHA_AV>

2019-10-26 11:38:17.103 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.178.21:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>

2019-10-26 11:38:17.115 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response

2019-10-26 11:38:17.120 [TRACE] [rnal.protocol.xml.XMLProtocolService] - Zone Main_Zone - inputs: Spotify:RW, JUKE:RW, AirPlay:RW, MusicCast Link:RW, SERVER:RW, NET RADIO:RW, Bluetooth:R, USB:R, iPod (USB):R, TUNER:R, HDMI1:R, HDMI2:RW, HDMI3:R, HDMI4:R, HDMI5:R, HDMI6:R, AV1:R, AV2:R, AV3:R, AV4:R, AUDIO1:R, AUDIO2:RW, AUX:R

2019-10-26 11:38:17.120 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name Spotify to Spotify - as per no conversion rule

2019-10-26 11:38:17.120 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name JUKE to JUKE - as per legacy mapping

2019-10-26 11:38:17.120 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AirPlay to AIRPLAY - as per legacy mapping

2019-10-26 11:38:17.121 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name MusicCast Link to MusicCast Link - as per no conversion rule

2019-10-26 11:38:17.121 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name SERVER to SERVER - as per legacy mapping

2019-10-26 11:38:17.121 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name NET RADIO to NET RADIO - as per no conversion rule

2019-10-26 11:38:17.121 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name HDMI2 to HDMI2 - as per no conversion rule

2019-10-26 11:38:17.121 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AUDIO2 to AUDIO2 - as per no conversion rule

2019-10-26 11:38:17.121 [TRACE] [.protocol.xml.ZoneAvailableInputsXML] - Zone Main_Zone - available inputs: AIRPLAY, AUDIO2, HDMI2, JUKE, MusicCast Link, NET RADIO, SERVER, Spotify

==> /openhab/userdata/logs/events.log <==

2019-10-26 11:38:17.123 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0ded43a90:Main_Zone' has been updated.

==> /openhab/userdata/logs/openhab.log <==

2019-10-26 11:38:17.124 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response

2019-10-26 11:38:17.126 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name NET RADIO to NET RADIO - as per no conversion rule

2019-10-26 11:38:17.126 [DEBUG] [internal.protocol.xml.ZoneControlXML] - Zone Main_Zone state - power: true, mute: false, volumeDB: -57.0, input: NET RADIO, surroundProgram: 2ch Stereo

==> /openhab/userdata/logs/events.log <==

2019-10-26 11:38:17.127 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0ded43a90:Main_Zone' changed from OFFLINE (CONFIGURATION_ERROR): connect timed out to ONLINE

Here is (part of my) my docker-compose.yml

# Openhab - Heimautomation
  openhab:
    container_name: openhab
    image: openhab/openhab:milestone
    restart: always
    network_mode: host
    volumes:
      - /etc/localtime:/etc/localtime:ro
      - /etc/timezone:/etc/timezone:ro
      - /opt/openhab/addons:/openhab/addons
      - /opt/openhab/conf:/openhab/conf
      - /opt/openhab/userdata:/openhab/userdata
    environment:
      OPENHAB_HTTP_PORT: "8080"
      OPENHAB_HTTPS_PORT: "8443"
      EXTRA_JAVA_OPTS: "-Duser.timezone=Europe/Berlin"

After changing from openhabian to docker, I just noticed the following warnings on startup:

[WARN ] [g.eclipse.smarthome.core.net.NetUtil] - Found multiple local interfaces - ignoring 192.168.178.150
[WARN ] [g.eclipse.smarthome.core.net.NetUtil] - Found multiple local interfaces - ignoring 192.168.178.150
[INFO ] [.network.internal.utils.NetworkUtils] - CIDR prefix is smaller than /24 on interface with address 172.18.0.1/16, truncating to /24, some addresses might be lost

Everything else is working fine. Any Ideas where to start?

Thanks a lot!

Hi

Are you sure that it is connected to Docker? I’m using openhabian only and get the same time out since updating to 2.5M4.

It worked fine with M3.

Anybody else having issues with Yamaha AVR Binding on latest milestone or can confirm it is working on his side?

Hi,

I do have timeout since 2.5M4 too with my RXV 485 … Yamaha Binding are not working for me anymore.

2019-11-02 11:22:41.873 [WARN ] [internal.protocol.xml.ZoneControlXML] - Could not perform feature detection for RX-V3900

java.net.SocketTimeoutException: connect timed out

2019-11-02 11:34:43.354 [hingStatusInfoChangedEvent] - ‘yamahareceiver:yamahaAV:9ab0c000_f668_11de_9976_bc30d919bdee’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): connect timed out

2019-11-02 11:34:43.981 [hingStatusInfoChangedEvent] - ‘yamahareceiver:zone:9ab0c000_f668_11de_9976_bc30d919bdee:Main_Zone’ changed from OFFLINE (CONFIGURATION_ERROR): connect timed out to OFFLINE (BRIDGE_OFFLINE)

I tried to remove the plug in and clear cache and then add again the plug in, but nothing works …

My Items are not working anymore …

Something has break the bindings.

Here with latest build of the bindings (2.5.0.201911020354) and log level debug :

2019-11-02 12:27:45.723 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.86.219:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd=“GET”><Power_Control>GetParam</Power_Control></YAMAHA_AV>

2019-11-02 12:27:45.733 [DEBUG] [internal.handler.YamahaBridgeHandler] - Communication error. Either the Yamaha thing configuration is invalid or the device is offline. Details: connect timed out

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

2019-11-02 12:27:45.741 [hingStatusInfoChangedEvent] - ‘yamahareceiver:yamahaAV:9ab0c000_f668_11de_9976_bc30d919bdee’ changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): connect timed out

2019-11-02 12:27:45.748 [hingStatusInfoChangedEvent] - ‘yamahareceiver:zone:9ab0c000_f668_11de_9976_bc30d919bdee:Main_Zone’ changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

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

2019-11-02 12:28:45.742 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.86.219:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd=“GET”><Power_Control>GetParam</Power_Control></YAMAHA_AV>

2019-11-02 12:28:45.753 [DEBUG] [internal.handler.YamahaBridgeHandler] - Communication error. Either the Yamaha thing configuration is invalid or the device is offline. Details: connect timed out

Hi,
I

  • am on 2.5-M4 and use a cubietruck with armbian linux
  • own a RX-V685
  • also get the timeouts for feature detection of RX-V3900
  • observed that in rules a sequence of settings send to my RX-V685 do not work
  • have to call the rule several times which in observed cases make all command being executed
  • added call to Thread::Sleep(250) between switching on Zone2 and Mainzone;
    since that time I did not realize that a command is not executed
    did not realize this behavior before 2.5-M4

Sorry for the late reply

You’re right. I used openhabian 2.5.0 M3. In Docker I am now back from M4 to M3 and everything works. No connect timed out anymore. So this seems to be an issue with M4.

I can confirm it. Problem with Pi4 and Openhabian 2.5M4.

But i have always

2019-11-15 14:01:42.343 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0de711e58:Zone_2' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR): connect timed out

2019-11-15 14:01:42.347 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0de711e58:Main_Zone' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR): connect timed out

2019-11-15 14:01:42.365 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0de711e58:Zone_2' changed from OFFLINE (CONFIGURATION_ERROR): connect timed out to ONLINE

2019-11-15 14:01:42.396 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0de711e58:Main_Zone' changed from OFFLINE (CONFIGURATION_ERROR): connect timed out to ONLINE

On OH 2.4 was ok.

Hi,
I

  • am on 2.5-M5 on a Raspberry Pi with Openhabian
  • own a RX-V671
  • also get the timeouts for feature detection of RX-V3900 (now with really long exceptions)

Is there a solution on the way?

Hello,

i got a similar problem with 2.5M5 and 2.5M6: My RX-V775 is always switching between online and connection error.

19:59:02.716 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'yamahareceiver:zone:5f9ec1b3_ed59_1900_4530_00a0dea3719a:ZoneID2' has been updated.
19:59:02.822 [INFO ] [smarthome.event.ThingUpdatedEvent    ] - Thing 'yamahareceiver:zone:5f9ec1b3_ed59_1900_4530_00a0dea3719a:ZoneID1' has been updated.
20:00:02.874 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:5f9ec1b3_ed59_1900_4530_00a0dea3719a' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): connect timed out
20:00:02.878 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'yamahareceiver:zone:5f9ec1b3_ed59_1900_4530_00a0dea3719a:ZoneID2' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
20:00:02.883 [INFO ] [ome.event.ThingStatusInfoChangedEvent] - 'yamahareceiver:zone:5f9ec1b3_ed59_1900_4530_00a0dea3719a:ZoneID1' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)
20:00:23.043 [WARN ] [.internal.protocol.xml.ZoneControlXML] - Could not perform feature detection for RX-V3900
java.net.SocketTimeoutException: connect timed out
        at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:1.8.0_232]
        at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[?:1.8.0_232]
        at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[?:1.8.0_232]
        at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[?:1.8.0_232]
        at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[?:1.8.0_232]
        at java.net.Socket.connect(Socket.java:607) ~[?:1.8.0_232]
        at sun.net.NetworkClient.doConnect(NetworkClient.java:175) ~[?:1.8.0_232]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:463) ~[?:1.8.0_232]
        at sun.net.www.http.HttpClient.openServer(HttpClient.java:558) ~[?:1.8.0_232]
        at sun.net.www.http.HttpClient.<init>(HttpClient.java:242) ~[?:1.8.0_232]
        at sun.net.www.http.HttpClient.New(HttpClient.java:339) ~[?:1.8.0_232]
        at sun.net.www.http.HttpClient.New(HttpClient.java:357) ~[?:1.8.0_232]
        at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1226) ~[?:1.8.0_232]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1162) ~[?:1.8.0_232]
        at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1056) ~[?:1.8.0_232]
        at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:990) ~[?:1.8.0_232]
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1340) ~[?:1.8.0_232]
        at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1315) ~[?:1.8.0_232]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLConnection.postMessage(XMLConnection.java:83) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLConnection.sendReceive(XMLConnection.java:121) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getResponse(XMLProtocolService.java:82) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getZoneResponse(XMLProtocolService.java:68) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.ZoneControlXML.applyModelVariations(ZoneControlXML.java:135) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.ZoneControlXML.<init>(ZoneControlXML.java:94) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolFactory.ZoneControl(XMLProtocolFactory.java:101) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.handler.YamahaZoneThingHandler.bridgeStatusChanged(YamahaZoneThingHandler.java:213) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.handler.YamahaBridgeHandler.updateAllZoneInformation(YamahaBridgeHandler.java:261) ~[?:?]
        at org.openhab.binding.yamahareceiver.internal.handler.YamahaBridgeHandler.lambda$0(YamahaBridgeHandler.java:217) ~[?:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_232]
        at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308) [?:1.8.0_232]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_232]
        at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294) [?:1.8.0_232]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_232]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_232]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_232]

Same issue on the new 2.5.0 released.

I have tested the Yamaha binding with latest OH 2.5.0 and was able to reproduce the issue.

A custom build containing the fix is available here.

  1. Uninstall stock Yamaha Binding
  2. Add my version of the binding to the addons folder

I recommend testing with OH 2.5.0.

Could you guys please test and report if it solved the problem?

Thanks a lot! Test started…

1 Like

Sorry, still the same error, started trace-logging.

Here, the fix solves the problem.

1 Like

I´ve tested it with 2.5.0. Around one hour after startup the first connect timed out appeared. I will continue testing.

2019-12-20 09:35:55.760 [TRACE] [internal.handler.YamahaBridgeHandler] - updateAllZoneInformation

2019-12-20 09:35:55.761 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.178.21:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><System><Power_Control><Power>GetParam</Power></Power_Control></System></YAMAHA_AV>

2019-12-20 09:35:55.768 [DEBUG] [internal.handler.YamahaBridgeHandler] - Communication error. Either the Yamaha thing configuration is invalid or the device is offline. Details: connect timed out

==> /openhab/userdata/logs/events.log <==

2019-12-20 09:35:55.768 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:9ab0c000_f668_11de_9976_00a0ded43a90' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): connect timed out

2019-12-20 09:35:55.769 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0ded43a90:Main_Zone' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

==> /openhab/userdata/logs/openhab.log <==

2019-12-20 09:41:55.768 [TRACE] [internal.handler.YamahaBridgeHandler] - updateAllZoneInformation

2019-12-20 09:41:55.769 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.178.21:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><System><Power_Control><Power>GetParam</Power></Power_Control></System></YAMAHA_AV>

2019-12-20 09:41:55.781 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response

2019-12-20 09:41:55.782 [DEBUG] [ternal.protocol.xml.SystemControlXML] - System state - power: false, partyMode: false

==> /openhab/userdata/logs/events.log <==

2019-12-20 09:41:55.783 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:9ab0c000_f668_11de_9976_00a0ded43a90' changed from OFFLINE (COMMUNICATION_ERROR): connect timed out to ONLINE

==> /openhab/userdata/logs/openhab.log <==

2019-12-20 09:41:55.784 [TRACE] [internal.protocol.xml.ZoneControlXML] - Zone Main_Zone - compatibility detection

2019-12-20 09:41:55.784 [DEBUG] [internal.protocol.xml.ZoneControlXML] - Zone Main_Zone - adjusting command to: <Sound_Video><Dialogue_Adjust><Dialogue_Lift>%d</Dialogue_Lift></Dialogue_Adjust></Sound_Video>

2019-12-20 09:41:55.785 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.178.21:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>

2019-12-20 09:41:55.786 [TRACE] [internal.protocol.xml.ZoneControlXML] - Zone Main_Zone - compatibility detection

2019-12-20 09:41:55.787 [DEBUG] [internal.protocol.xml.ZoneControlXML] - Zone Main_Zone - adjusting command to: <Sound_Video><Dialogue_Adjust><Dialogue_Lift>%d</Dialogue_Lift></Dialogue_Adjust></Sound_Video>

2019-12-20 09:41:55.788 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.178.21:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>

2019-12-20 09:41:55.795 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response

2019-12-20 09:41:55.795 [WARN ] [internal.protocol.xml.ZoneControlXML] - Could not perform feature detection for RX-V3900

java.net.SocketTimeoutException: connect timed out

	at java.net.PlainSocketImpl.socketConnect(Native Method) ~[?:1.8.0_232]

	at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[?:1.8.0_232]

	at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[?:1.8.0_232]

	at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[?:1.8.0_232]

	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[?:1.8.0_232]

	at java.net.Socket.connect(Socket.java:607) ~[?:1.8.0_232]

	at sun.net.NetworkClient.doConnect(NetworkClient.java:175) ~[?:1.8.0_232]

	at sun.net.www.http.HttpClient.openServer(HttpClient.java:463) ~[?:1.8.0_232]

	at sun.net.www.http.HttpClient.openServer(HttpClient.java:558) ~[?:1.8.0_232]

	at sun.net.www.http.HttpClient.<init>(HttpClient.java:242) ~[?:1.8.0_232]

	at sun.net.www.http.HttpClient.New(HttpClient.java:339) ~[?:1.8.0_232]

	at sun.net.www.http.HttpClient.New(HttpClient.java:357) ~[?:1.8.0_232]

	at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1226) ~[?:1.8.0_232]

	at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1162) ~[?:1.8.0_232]

	at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1056) ~[?:1.8.0_232]

	at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:990) ~[?:1.8.0_232]

	at sun.net.www.protocol.http.HttpURLConnection.getOutputStream0(HttpURLConnection.java:1340) ~[?:1.8.0_232]

	at sun.net.www.protocol.http.HttpURLConnection.getOutputStream(HttpURLConnection.java:1315) ~[?:1.8.0_232]

	at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLConnection.postMessage(XMLConnection.java:83) ~[bundleFile:?]

	at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLConnection.sendReceive(XMLConnection.java:121) ~[bundleFile:?]

	at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getResponse(XMLProtocolService.java:82) ~[bundleFile:?]

	at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolService.getZoneResponse(XMLProtocolService.java:68) ~[bundleFile:?]

	at org.openhab.binding.yamahareceiver.internal.protocol.xml.ZoneControlXML.applyModelVariations(ZoneControlXML.java:135) [bundleFile:?]

	at org.openhab.binding.yamahareceiver.internal.protocol.xml.ZoneControlXML.<init>(ZoneControlXML.java:94) [bundleFile:?]

	at org.openhab.binding.yamahareceiver.internal.protocol.xml.XMLProtocolFactory.ZoneControl(XMLProtocolFactory.java:101) [bundleFile:?]

	at org.openhab.binding.yamahareceiver.internal.handler.YamahaZoneThingHandler.bridgeStatusChanged(YamahaZoneThingHandler.java:213) [bundleFile:?]

	at org.eclipse.smarthome.core.thing.internal.ThingManagerImpl$4.run(ThingManagerImpl.java:884) [bundleFile:?]

	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_232]

	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_232]

	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_232]

	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_232]

	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_232]

	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_232]

	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_232]

2019-12-20 09:41:55.804 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.178.21:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>

==> /openhab/userdata/logs/events.log <==

2019-12-20 09:41:55.805 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0ded43a90:Main_Zone' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE

==> /openhab/userdata/logs/openhab.log <==

2019-12-20 09:41:55.805 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.178.21:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Input><Input_Sel_Item>GetParam</Input_Sel_Item></Input></Main_Zone></YAMAHA_AV>

2019-12-20 09:41:55.833 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.178.21:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Input><Input_Sel_Item>GetParam</Input_Sel_Item></Input></Main_Zone></YAMAHA_AV>

2019-12-20 09:41:55.833 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.178.21:80/YamahaRemoteControl/ctrl with payload: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>

==> /openhab/userdata/logs/events.log <==

2019-12-20 09:41:55.856 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0ded43a90:Main_Zone' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR): connect timed out

==> /openhab/userdata/logs/openhab.log <==

2019-12-20 09:41:55.867 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response

2019-12-20 09:41:55.868 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response

2019-12-20 09:41:55.878 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AUDIO1 to AUDIO1 - as per legacy mapping

2019-12-20 09:41:55.881 [DEBUG] [internal.protocol.xml.ZoneControlXML] - Zone Main_Zone state - power: false, mute: false, volumeDB: -55.0, input: AUDIO1, surroundProgram: Straight

==> /openhab/userdata/logs/events.log <==

2019-12-20 09:41:55.883 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0ded43a90:Main_Zone' changed from OFFLINE (CONFIGURATION_ERROR): connect timed out to ONLINE

==> /openhab/userdata/logs/openhab.log <==

2019-12-20 09:41:55.888 [TRACE] [rnal.protocol.xml.XMLProtocolService] - Zone Main_Zone - inputs: Spotify:RW, JUKE:RW, AirPlay:RW, MusicCast Link:RW, SERVER:RW, NET RADIO:RW, Bluetooth:R, USB:R, iPod (USB):R, TUNER:R, HDMI1:R, HDMI2:RW, HDMI3:R, HDMI4:R, HDMI5:R, HDMI6:R, AV1:R, AV2:R, AV3:R, AV4:R, AUDIO1:R, AUDIO2:RW, AUX:R

2019-12-20 09:41:55.888 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name Spotify to Spotify - as per no conversion rule

2019-12-20 09:41:55.888 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name JUKE to JUKE - as per legacy mapping

2019-12-20 09:41:55.895 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AirPlay to AIRPLAY - as per legacy mapping

2019-12-20 09:41:55.896 [TRACE] [.internal.protocol.xml.XMLConnection] - The charset UTF-8 will be used to parse the response

2019-12-20 09:41:55.895 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name MusicCast Link to MusicCast Link - as per no conversion rule

2019-12-20 09:41:55.896 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name SERVER to SERVER - as per legacy mapping

2019-12-20 09:41:55.897 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name NET RADIO to NET RADIO - as per no conversion rule

2019-12-20 09:41:55.898 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name HDMI2 to HDMI2 - as per no conversion rule

2019-12-20 09:41:55.898 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AUDIO2 to AUDIO2 - as per no conversion rule

2019-12-20 09:41:55.899 [TRACE] [.protocol.xml.ZoneAvailableInputsXML] - Zone Main_Zone - available inputs: AIRPLAY, AUDIO2, HDMI2, JUKE, MusicCast Link, NET RADIO, SERVER, Spotify

2019-12-20 09:41:55.902 [TRACE] [rnal.protocol.xml.XMLProtocolService] - Zone Main_Zone - inputs: Spotify:RW, JUKE:RW, AirPlay:RW, MusicCast Link:RW, SERVER:RW, NET RADIO:RW, Bluetooth:R, USB:R, iPod (USB):R, TUNER:R, HDMI1:R, HDMI2:RW, HDMI3:R, HDMI4:R, HDMI5:R, HDMI6:R, AV1:R, AV2:R, AV3:R, AV4:R, AUDIO1:R, AUDIO2:RW, AUX:R

2019-12-20 09:41:55.904 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name Spotify to Spotify - as per no conversion rule

==> /openhab/userdata/logs/events.log <==

2019-12-20 09:41:55.904 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0ded43a90:Main_Zone' has been updated.

==> /openhab/userdata/logs/openhab.log <==

2019-12-20 09:41:55.908 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name JUKE to JUKE - as per legacy mapping

2019-12-20 09:41:55.909 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AirPlay to AIRPLAY - as per legacy mapping

2019-12-20 09:41:55.910 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name MusicCast Link to MusicCast Link - as per no conversion rule

2019-12-20 09:41:55.911 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name SERVER to SERVER - as per legacy mapping

2019-12-20 09:41:55.912 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name NET RADIO to NET RADIO - as per no conversion rule

2019-12-20 09:41:55.923 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name HDMI2 to HDMI2 - as per no conversion rule

2019-12-20 09:41:55.924 [TRACE] [ernal.protocol.xml.InputConverterXML] - Converting from state name AUDIO2 to AUDIO2 - as per no conversion rule

2019-12-20 09:41:55.924 [TRACE] [.protocol.xml.ZoneAvailableInputsXML] - Zone Main_Zone - available inputs: AIRPLAY, AUDIO2, HDMI2, JUKE, MusicCast Link, NET RADIO, SERVER, Spotify

==> /openhab/userdata/logs/events.log <==

2019-12-20 09:41:55.937 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0ded43a90:Main_Zone' has been updated.

This log statement indicates you are not running my version of the Addon. With the fixes I’ve put in that log statement is at DEBUG level (to not annoy people).

Please make sure the stock addon is uninstaled and my custom build version is running (see link in my earlier post).

Cheers,
TM

Hi,
in my setup with 2.5.0 it has been a problem to execute several settings one after an other in a rule. Only one or the other setting was successfully executed. With the snapshot version this seems to run again / so far.
I do not see the “COMMUNICATION_ERROR” or “changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE” messages any longer.

What I still see ( not sure if that is intended ) are repeated messages like:

    2019-12-21 09:18:44.457 [vent.ItemStateChangedEvent] - RXV685Zone_2_Zone_channels_ changed from NULL to MAIN_ZONE_SYNC
    2019-12-21 09:18:44.471 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_4c1b8626444e:Main_Zone' has been updated.
    2019-12-21 09:18:44.551 [vent.ItemStateChangedEvent] - RXV685Main_Zone_Zone_channels_ changed from NULL to HDMI1
    2019-12-21 09:18:44.622 [vent.ItemStateChangedEvent] - RXV685Main_Zone_Zone_channels_Volume changed from NULL to 30
    2019-12-21 09:19:44.381 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_4c1b8626444e:Zone_2' has been updated.
    2019-12-21 09:19:44.610 [vent.ItemStateChangedEvent] - RXV685Zone_2_Zone_channels_ changed from NULL to MAIN_ZONE_SYNC
    2019-12-21 09:19:45.013 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_4c1b8626444e:Main_Zone' has been updated.
    2019-12-21 09:19:45.104 [vent.ItemStateChangedEvent] - RXV685Main_Zone_Zone_channels_ changed from NULL to HDMI1
    2019-12-21 09:19:45.156 [vent.ItemStateChangedEvent] - RXV685Main_Zone_Zone_channels_Volume changed from NULL to 30
    2019-12-21 09:20:44.471 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_4c1b8626444e:Zone_2' has been updated.
    2019-12-21 09:20:44.612 [vent.ItemStateChangedEvent] - RXV685Zone_2_Zone_channels_ changed from NULL to MAIN_ZONE_SYNC
    2019-12-21 09:20:44.897 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_4c1b8626444e:Main_Zone' has been updated.
    2019-12-21 09:20:45.017 [vent.ItemStateChangedEvent] - RXV685Main_Zone_Zone_channels_ changed from NULL to HDMI1
    2019-12-21 09:20:45.084 [vent.ItemStateChangedEvent] - RXV685Main_Zone_Zone_channels_Volume changed from NULL to 30
    2019-12-21 09:21:44.703 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_4c1b8626444e:Zone_2' has been updated.
    2019-12-21 09:21:44.843 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_4c1b8626444e:Main_Zone' has been updated.
    2019-12-21 09:21:44.970 [vent.ItemStateChangedEvent] - RXV685Zone_2_Zone_channels_ changed from NULL to MAIN_ZONE_SYNC
    2019-12-21 09:21:45.099 [vent.ItemStateChangedEvent] - RXV685Main_Zone_Zone_channels_ changed from NULL to HDMI1
    2019-12-21 09:21:45.131 [vent.ItemStateChangedEvent] - RXV685Main_Zone_Zone_channels_Volume changed from NULL to 30
    2019-12-21 09:22:45.046 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_4c1b8626444e:Main_Zone' has been updated.
    2019-12-21 09:22:45.162 [vent.ItemStateChangedEvent] - RXV685Main_Zone_Zone_channels_ changed from NULL to HDMI1
    2019-12-21 09:22:45.207 [vent.ItemStateChangedEvent] - RXV685Main_Zone_Zone_channels_Volume changed from NULL to 30
    2019-12-21 09:22:45.500 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_4c1b8626444e:Zone_2' has been updated.
    2019-12-21 09:22:45.535 [vent.ItemStateChangedEvent] - RXV685Zone_2_Zone_channels_ changed from NULL to MAIN_ZONE_SYNC
    2019-12-21 09:23:44.989 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_4c1b8626444e:Zone_2' has been updated.
    2019-12-21 09:23:45.055 [vent.ItemStateChangedEvent] - RXV685Zone_2_Zone_channels_ changed from NULL to MAIN_ZONE_SYNC
    2019-12-21 09:23:45.353 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_4c1b8626444e:Main_Zone' has been updated.
    2019-12-21 09:23:45.468 [vent.ItemStateChangedEvent] - RXV685Main_Zone_Zone_channels_ changed from NULL to HDMI1
    2019-12-21 09:23:45.544 [vent.ItemStateChangedEvent] - RXV685Main_Zone_Zone_channels_Volume changed from NULL to 30
1 Like

The Yamaha main thing and zone things are periodically polling latest state updates from the Yamaha device. This is set in the configuration how often does it happen. Let say if it is set to 30 seconds, you see these event logs every 30 seconds or so. Default is at 60 seconds. More here.

To reduce the chatter, at some point I was thinking to implement an optimization to the addon to not update a OH channel in case the value didn’t change, but never got the time to do this…

1 Like

I followed your instructions. But because I was doing several things at once, I forgot to do a clean restart with cleaning up /tmp and /cache :see_no_evil: After I´ve done so, everything is up and working fine for hours. Sorry for bothering and thanks a lot for the work!

1 Like