[yamahareceiver] connect timed out since 2.5M4

[ozirissp]

Since update 2.5M4 the Yamaha Binding with my Yamaha RX-V485 is not working anymore.

I tried to uninstall the binding then clear the cache and reinstall ...

I also tried the latest version from snapshot : 2.5.0.201911020354

2019-11-02 12:32:45.945 [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"><System><Power_Control><Power>GetParam</Power></Power_Control></System></YAMAHA_AV>

2019-11-02 12:32:45.955 [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:32:45.963 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:9ab0c000_f668_11de_9976_bc30d919bdee' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): connect timed out

2019-11-02 12:32:45.972 [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:33:45.962 [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"><System><Power_Control><Power>GetParam</Power></Power_Control></System></YAMAHA_AV>

2019-11-02 12:33:46.023 [DEBUG] [ternal.protocol.xml.SystemControlXML] - System state - power: false, partyMode: false

2019-11-02 12:33:46.030 [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"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>

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

2019-11-02 12:33:46.038 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:9ab0c000_f668_11de_9976_bc30d919bdee' changed from OFFLINE (COMMUNICATION_ERROR): connect timed out to ONLINE

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

2019-11-02 12:33:46.036 [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"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>

2019-11-02 12:33:46.115 [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"><Main_Zone><Input><Input_Sel_Item>GetParam</Input_Sel_Item></Input></Main_Zone></YAMAHA_AV>

2019-11-02 12:33:46.115 [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"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>

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

2019-11-02 12:33:46.127 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_bc30d919bdee:Main_Zone' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE

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

2019-11-02 12:33:46.157 [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"><Main_Zone><Input><Input_Sel_Item>GetParam</Input_Sel_Item></Input></Main_Zone></YAMAHA_AV>

2019-11-02 12:33:46.158 [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"><Main_Zone><Basic_Status>GetParam</Basic_Status></Main_Zone></YAMAHA_AV>

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

2019-11-02 12:33:46.239 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_bc30d919bdee:Main_Zone' has been updated.

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

2019-11-02 12:33:46.243 [DEBUG] [internal.protocol.xml.ZoneControlXML] - Zone Main_Zone state - power: false, mute: false, volumeDB: -51.0, input: HDMI3, surroundProgram: Straight

2019-11-02 12:33:46.339 [DEBUG] [internal.protocol.xml.ZoneControlXML] - Zone Main_Zone state - power: false, mute: false, volumeDB: -51.0, input: HDMI3, surroundProgram: Straight

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

2019-11-02 12:33:46.527 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_bc30d919bdee:Main_Zone' has been updated.

And also a bad warning for device detection ...

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

java.net.SocketTimeoutException: connect timed out

See the forum here : communty thread

I use Openhabian on my Raspberry Pi 3 updated to the latest Milestone 2.5M4
My Yahama Receiver RX-V485 has the latest firmware (and was working fine before the update to the 2.5M4).

[RestOp]

I can confirm it. Problem with Pi4 and OH 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]

I also get the timeouts for feature detection of RX-V3900 (now with really long exceptions).
OH 2.5-M6 on a Raspberry Pi with Openhabian with Yamaha RX-V671

[zarusz]

I am on the OH 2.5-SNAPSHOT and do not see any issues.
Will update my environment to M6 and see if I can repro the issue...

[KenkiCK]

The message : "Could not perform feature detection for RX-V3900" - I get it too for Yamaha RX-601D. But the receiver itself works. OH2.5 M6.
Can you check with a ping the rceiver from you openhab platform or the IP of the receiver ? looks mor like a network issue for me. The warning itself is not really relvant.

One more idea, can you open the receiver url with a browser on the platform where openhab runs ?

[zarusz]

Hi @ozirissp are you able to open any of the following URLs from your browser while on local network? The browser should display (or donwnload) an XML file.

http://192.168.86.219:80/YamahaRemoteControl/desc.xml
http://192.168.86.219:80/YamahaRemoteControl/UnitDesc.xml

I would like to rule out the network connectivity issues as suggested by @KenkiCK .

If the yamaha receiver is getting different IPs in your home network the binding would not be able to reach it on 192.168.86.219. Static IPs assignments should be configured on the router, so that the device always gets the same IP.

@michel53 and @RestOp could you guys also try the above URLs (with your counter part IPs)?

[ozirissp]

Hi @zarusz ,

I am only able to get the first xml (desc.xml)

desc.xml.txt
or on pastebin :
https://pastebin.com/EXnjZagx

The second enpoint (UnitDesc.xml) seems to not exist on my yahama device.

Sometimes the bindings works (but it keeps going OFFLINE) ... I still get this kind of LOG :

2019-12-08 18:24:25.528 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:9ab0c000_f668_11de_9976_bc30d919bdee' changed from OFFLINE (COMMUNICATION_ERROR): connect timed out to ONLINE

2019-12-08 18:24:25.645 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_bc30d919bdee:Main_Zone' changed from OFFLINE (BRIDGE_OFFLINE) to ONLINE

2019-12-08 18:24:25.691 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_bc30d919bdee:Main_Zone' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR)

2019-12-08 18:24:25.701 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_bc30d919bdee:Main_Zone' changed from OFFLINE (CONFIGURATION_ERROR) to ONLINE

2019-12-08 18:24:25.780 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_bc30d919bdee:Main_Zone' has been updated.

2019-12-08 18:25:25.625 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:9ab0c000_f668_11de_9976_bc30d919bdee' changed from ONLINE to OFFLINE (COMMUNICATION_ERROR): connect timed out

2019-12-08 18:25:25.628 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_bc30d919bdee:Main_Zone' changed from ONLINE to OFFLINE (BRIDGE_OFFLINE)

Thanks for your help.

[zarusz]

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?

[emiksTT]

@zarusz
With this fix problem is gone, thanks.

Pozdro

[michel53]

With the fix, the problem is gone for me, too.
I own a RX-V671.

[ozirissp]

@zarusz Perfect !

This solve the problem for me too !

Thanks did you open a pull request ?

[zarusz]

@ozirissp I plan to open the PR once I get enough testing proof from the community. Should be pretty soon.

[zarusz]

On my receiver I am still observing one more glitch (see below). I will look into this and provide a new build JAR.

2019-12-21 07:44:29.504 [DEBUG] [ernal.handler.YamahaZoneThingHandler] - State update error. Changing thing to offline
java.io.IOException: Menu still not ready after 5000ms
	at org.openhab.binding.yamahareceiver.internal.protocol.xml.InputWithNavigationControlXML.update(InputWithNavigationControlXML.java:300) ~[?:?]
	at org.openhab.binding.yamahareceiver.internal.handler.YamahaZoneThingHandler.lambda$2(YamahaZoneThingHandler.java:723) ~[?:?]
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [?:1.8.0_222]
	at java.util.concurrent.FutureTask.run(FutureTask.java:266) [?:1.8.0_222]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) [?:1.8.0_222]
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) [?:1.8.0_222]
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [?:1.8.0_222]
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [?:1.8.0_222]
	at java.lang.Thread.run(Thread.java:748) [?:1.8.0_222]
2019-12-21 07:44:33.769 [DEBUG] [.internal.protocol.xml.XMLConnection] - Making POST to http://192.168.1.131: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>

[cauer71]

The fixed jar solved the Problem for me on a HTR4069 and Openhab 2.5 RC

[cauer71]

after installing the fix i have reproducible delay of approx. 5 -6 seconds for all rules.
Iis it possible to test the jar from 2.4? where can i find it?

[zarusz]

@cauer71 can you please provide some more details (and logs) on the said delay?

Regarding the binding build for 2.4, I am not sure if there is any automated way to build these. I think I would have to rebase my fixes against 2.4 binding and built it locally.
Do you think the 2.4 version will improve anything?

[zarusz]

I have fixed the last glitch mentioned here.
The latest build is org.openhab.binding.yamahareceiver-2.5.2-SNAPSHOT.jar available as usual here.

Please report if you see any issues.

I will create PR and hopefully the fix will make its way into 2.5.2 release.

[cauer71]

The last fix does not work for me:

2020-01-19 18:06:25.597 [me.event.InboxRemovedEvent] - Discovery Result with UID 'yamahareceiver:yamahaAV:9ab0c000_f668_11de_9976_00a0ded9eafd' has been removed.
2020-01-19 18:06:25.629 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:9ab0c000_f668_11de_9976_00a0ded9eafd' changed from UNINITIALIZED to INITIALIZING
2020-01-19 18:06:25.671 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:9ab0c000_f668_11de_9976_00a0ded9eafd' changed from INITIALIZING to OFFLINE (CONFIGURATION_PENDING): Waiting for connection with Yamaha device
==> /var/log/openhab2/openhab.log <==
2020-01-19 18:06:25.678 [WARN ] [internal.handler.YamahaBridgeHandler] - Communication error. Please review your Yamaha thing configuration.
==> /var/log/openhab2/events.log <==
2020-01-19 18:06:25.679 [hingStatusInfoChangedEvent] - 'yamahareceiver:yamahaAV:9ab0c000_f668_11de_9976_00a0ded9eafd' changed from OFFLINE (CONFIGURATION_PENDING): Waiting for connection with Yamaha device to OFFLINE (COMMUNICATION_ERROR): connect timed out

desc.txt
UnitDesc.xml does not exist on the HTR-4069

with the this version i had no delay in executing the rules.
i couldn't find anything in the logs last time, it seemed that openhab waited a few seconds each time until rules were executed. when i deleted the fixed plugin, everything worked fine

[zarusz]

@cauer71 the below WARN is generated only when the binding is initializing:

2020-01-19 18:06:25.678 [WARN ] [internal.handler.YamahaBridgeHandler] - Communication error. Please review your Yamaha thing configuration.

When no connectivity to device is detected during init phase, the bridge thing will be put to OFFLINE state.
Based on that, I suspect that either the old binding was cached or the host/port might have been cached by Karaf.

Few ideas:

1. Clear caches
2. Double check host/ip/port settings on the thing
3. Enable trace logging, to see the below statement on addon initialization (this might show if valid values are getting to the bridge thing):

        logger.trace("Initialize of {} with host '{}' and port {}"

[cauer71]

you're right, I mistakenly had the original plugin and the patched version online at the same time :-(
the current version works fine, i will continue to test it now. thanks a lot

[cauer71]

is it the intention that items are first set to NULL on an update and then get their actual value?

2020-01-29 08:05:21.014 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_00a0ded9eafd:Main_Zone' has been updated.

2020-01-29 08:05:21.035 [vent.ItemStateChangedEvent] - yamahareceiver_zone_9ab0c000_f668_11de_9976_00a0ded9eafd_Main_Zone_zone_channels_mute changed from **NULL to OFF**

2020-01-29 08:05:21.038 [vent.ItemStateChangedEvent] - yamahareceiver_zone_9ab0c000_f668_11de_9976_00a0ded9eafd_Main_Zone_zone_channels_dialogueLevel changed from **NULL to 1**

2020-01-29 08:05:21.041 [vent.ItemStateChangedEvent] - yamahareceiver_zone_9ab0c000_f668_11de_9976_00a0ded9eafd_Main_Zone_playback_channels_playback changed from **NULL to Play**