Yamaha Receiver Binding - connect timed out

liveislife · November 3, 2019, 9:34am

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.

thisisIO · November 15, 2019, 1:08pm

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.

michel53 · November 22, 2019, 9:32am

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?

e36Alex · December 7, 2019, 7:01pm

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]

Bucofski · December 16, 2019, 6:12pm

Same issue on the new 2.5.0 released.

zarusz · December 17, 2019, 11:52pm

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.

Uninstall stock Yamaha Binding
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?

liveislife · December 20, 2019, 7:03am

Thanks a lot! Test started…

liveislife · December 20, 2019, 8:18am

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

michel53 · December 20, 2019, 8:27am

Here, the fix solves the problem.

liveislife · December 20, 2019, 8:35am

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

liveislife · December 20, 2019, 8:45am

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.

zarusz · December 20, 2019, 11:05pm

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

Wolfgang_S · December 21, 2019, 8:29am

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

zarusz · December 21, 2019, 8:58am

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…

liveislife · December 21, 2019, 9:25am

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 After I´ve done so, everything is up and working fine for hours. Sorry for bothering and thanks a lot for the work!

olialb · January 4, 2020, 8:00am

Hello @zarusz,

thanks for working on a fix. I have the same issue. Is there any plan to push your fixes it in the official binding soon?

zarusz · January 4, 2020, 8:10am

Hi @olialb, I will create a pull request soon. I will also want to fix this but just struggling with time at the moment.

olialb · January 4, 2020, 8:15am

Great! Thanks for quick response!! Would be great if it comes together with the 2.5.1 update already.

marcin_st · January 10, 2020, 5:35pm

Are you going also to put this optimization soon with other fixes?

zarusz · January 14, 2020, 8:45pm

Please see the progress here

@marcin_st the event update log optimizations will come as another improvement PR. The timeout issue more critical atm.