[yamahaReceiver] Thing goes offline due to CONFIGURATION_ERROR

[ddt3]

After installing the binding 3 Things are discoverd: Yamaha Receiver RX-V685 RX-V685 Main_Zone RX-V685 Zone_2

Both RX-V685 Main_Zone RX-V685 Zone_2

Switch from Online to Offline and from Offline to Online again.

2020-05-18 08:03:32.803 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_f086206cf828:Main_Zone' has been updated. 2020-05-18 08:04:32.390 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_f086206cf828:Zone_2' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR): Changing a value on the Yamaha AVR failed: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Spotify><Play_Control><Preset><Preset_Sel_Item>GetParam</Preset_Sel_Item></Preset></Play_Control></Spotify></YAMAHA_AV> 2020-05-18 08:04:32.475 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_f086206cf828:Zone_2' changed from OFFLINE (CONFIGURATION_ERROR): Changing a value on the Yamaha AVR failed: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Spotify><Play_Control><Preset><Preset_Sel_Item>GetParam</Preset_Sel_Item></Preset></Play_Control></Spotify></YAMAHA_AV> to ONLINE 2020-05-18 08:04:32.578 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_f086206cf828:Zone_2' has been updated. 2020-05-18 08:04:32.614 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_f086206cf828:Main_Zone' has been updated. 2020-05-18 08:05:32.507 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_f086206cf828:Zone_2' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR): Changing a value on the Yamaha AVR failed: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Spotify><Play_Control><Preset><Preset_Sel_Item>GetParam</Preset_Sel_Item></Preset></Play_Control></Spotify></YAMAHA_AV> 2020-05-18 08:05:32.609 [hingStatusInfoChangedEvent] - 'yamahareceiver:zone:9ab0c000_f668_11de_9976_f086206cf828:Zone_2' changed from OFFLINE (CONFIGURATION_ERROR): Changing a value on the Yamaha AVR failed: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Spotify><Play_Control><Preset><Preset_Sel_Item>GetParam</Preset_Sel_Item></Preset></Play_Control></Spotify></YAMAHA_AV> to ONLINE 2020-05-18 08:05:32.724 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_f086206cf828:Zone_2' has been updated. 2020-05-18 08:05:32.763 [me.event.ThingUpdatedEvent] - Thing 'yamahareceiver:zone:9ab0c000_f668_11de_9976_f086206cf828:Main_Zone' has been updated.

I have removed the things and binding cleaned the openhab cache and started over again. That does not help, same behavior occurs. Because of this items do not have the actual current state,

Your Environment

• Version used: openHAB 2.5.5 running on openHABIAN. (and yamahareceiver 2.5.5)
• openjdk version "1.8.0_252"
• Linux openhab 4.19.97-v7+ (openHABIAN)
• Yamaha RX-V685 Firmware 1.8

[lolodomo]

CONFIGURATION_ERROR is certainly irrelevant. This should be replaced by COMMUNICATION_ERROR at line line: https://github.com/openhab/openhab-addons/blob/2.5.x/bundles/org.openhab.binding.yamahareceiver/src/main/java/org/openhab/binding/yamahareceiver/internal/handler/YamahaZoneThingHandler.java#L725

[ddt3]

Looking at that one might think that the error is caused by the network, so I did a simple check: From the opanHABian system to the yamaha receiver(192.168.3.144):

$ ping -i 10 -c100 192.168.3.144
--- 192.168.3.144 ping statistics ---
100 packets transmitted, 100 received, 0% packet loss, time 1863ms
rtt min/avg/max/mdev = 0.511/0.607/0.769/0.055 ms

Another system on the same network:

$ ping -i 10 -c 60 192.168.3.144--- 192.168.3.144 
ping statistics ---60 packets transmitted, 60 received, 0% packet loss, time 590097ms
rtt min/avg/max/mdev = 0.998/1.296/2.130/0.295 ms

[olemr]

Have you checked the java process CPU usage with top? Could it perhaps be related to this issue? https://github.com/openhab/openhab-addons/issues/7184#issuecomment-631720137

[ddt3]

Thanks for the info. I used 'for i in {1..400}; do sleep 2 && top -b -p 25442 -n1 | tail -1 ; done' (where 25442 is the java process) Result below, when the error happened the usage was about 6.7 percent. So don't think this one is related to #7184 . PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:00.66 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:00.92 java 25442 openhab 20 0 657636 421892 13372 S 26.7 42.2 329:01.00 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:01.18 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:01.56 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:01.65 java 25442 openhab 20 0 657636 421892 13372 S 6.2 42.2 329:01.69 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:02.14 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:02.35 java 25442 openhab 20 0 657636 421892 13372 S 33.3 42.2 329:02.50 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:02.63 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:02.72 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:03.02 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:03.06 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:03.25 java 25442 openhab 20 0 657636 421892 13372 S 46.7 42.2 329:03.68 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:03.90 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:03.97 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:04.68 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:05.10 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:05.25 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:05.32 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:05.35 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:05.68 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:05.72 java 25442 openhab 20 0 657636 421892 13372 S 6.2 42.2 329:05.81 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:05.95 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:06.11 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:06.17 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:06.23 java 25442 openhab 20 0 657636 421892 13372 S 86.7 42.2 329:06.61 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:06.80 java 25442 openhab 20 0 657636 421892 13372 S 20.0 42.2 329:06.87 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:06.93 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:07.41 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:07.46 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:07.53 java 25442 openhab 20 0 657636 421892 13372 S 12.5 42.2 329:07.68 java 25442 openhab 20 0 657636 421892 13372 S 20.0 42.2 329:08.28 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:08.80 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:08.85 java 25442 openhab 20 0 657636 421892 13372 S 6.2 42.2 329:08.95 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:09.27 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:09.46 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:09.56 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:10.05 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:10.38 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:10.57 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:10.63 java 25442 openhab 20 0 657636 421892 13372 S 73.3 42.2 329:10.98 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:11.05 java 25442 openhab 20 0 657636 421892 13372 S 20.0 42.2 329:11.20 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:11.26 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:11.58 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:11.62 java 25442 openhab 20 0 657636 421892 13372 S 13.3 42.2 329:11.70 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:11.87 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:12.20 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:12.37 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:12.44 java 25442 openhab 20 0 657636 421892 13372 S 26.7 42.2 329:12.59 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:12.83 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:13.51 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:13.55 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:13.91 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:14.05 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:14.22 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:14.27 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:14.49 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:15.08 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:15.52 java 25442 openhab 20 0 657636 421892 13372 S 12.5 42.2 329:15.63 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:15.85 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:16.54 java 25442 openhab 20 0 657636 421892 13372 S 6.2 42.2 329:16.67 java 25442 openhab 20 0 657636 421892 13372 S 6.2 42.2 329:17.02 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:17.12 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:17.16 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:17.32 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:17.38 java 25442 openhab 20 0 657636 421892 13372 S 20.0 42.2 329:17.58 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:17.71 java 25442 openhab 20 0 657636 421892 13372 S 6.7 42.2 329:17.77 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:17.84 java 25442 openhab 20 0 657636 421892 13372 S 20.0 42.2 329:17.93 java 25442 openhab 20 0 657636 421892 13372 S 0.0 42.2 329:18.22 java `

[darkogorgievski]

I hqve the same issue filling my log. Happens when the input of the receiver is spotify. I get the error even if the receiver is OFF. Changing the input to something else stops the log

Thing 'yamahareceiver:zone:YamahaAVLiving:YamahaLiving' changed from OFFLINE (CONFIGURATION_ERROR): Changing a value on the Yamaha AVR failed: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Spotify><Play_Control><Preset><Preset_Sel_Item>GetParam</Preset_Sel_Item></Preset></Play_Control></Spotify></YAMAHA_AV> to ONLINE

2022-10-02 20:04:55.758 [INFO ] [ab.event.ThingStatusInfoChangedEvent] - Thing 'yamahareceiver:zone:YamahaAVLiving:YamahaLiving' changed from ONLINE to OFFLINE (CONFIGURATION_ERROR): Changing a value on the Yamaha AVR failed: <?xml version="1.0" encoding="utf-8"?><YAMAHA_AV cmd="GET"><Spotify><Play_Control><Preset><Preset_Sel_Item>GetParam</Preset_Sel_Item></Preset></Play_Control></Spotify></YAMAHA_AV>

[lolodomo]

@darkogorgievski : please enable binding DEBUG logs and show these logs + the possible exception when the thing is switching to OFFLINE.

Edit: not necessary, I found in the code where the exception is thrown.

[lolodomo]

The binding is sending a request that fails when the input is Spotify. I have no idea if the request should be a little different in case of Spotify or if simply it should not be sent at all. In any case, that is a detail but CONFIGURATION_ERROR as detailed status is an inappropriate choice in that case. It should be rather COMMUNICATION_ERROR.