Hi,
Recently I upgraded from NHC-I to NHC-II. I removed all my things, added them again and linked everything back to the items. Now I have a huge delay on controlling the items.
Receiving the itemstates from the controller works always fine in a few ms.
After a reboot and clear-cache, it works for a few minutes, but then the delay starts to build up and after 2 days the delay is aprox 30 minutes.
Already disables all other things and rules but no solution.
Hardare is xeon 16cores with 64GB ram so that can’t be the issue.
What version of OH are you running?
Could you try turning on debug logging on the nikohomecontrol binding to see what is happening?
Don’t clear cache every time you restart. This will cause the binding the be downloaded and installed again and has no impact on the functioning, but to delay startup.
There is an advanced parameter on the niko home control bridge thing, refresh interval. Try setting it to something else than 0. I have it at 0 and have no issues. But it can be used to automatically restart the bridge every x minutes (try 300). I needed it to make NHC I work stable, but have not needed it for NHC II.
Running openHAB 4.1.0
Log file shows nothing. I can see in the log file that the item is updates but it is not passed to the channel. After the delay I can see that the thing is also updating and sending to NHC without errors.
I just removed and re-installed openhab and until now it is working fine. I used the backup-restore to re-install, so nothing changed on the config. I will check in a few hours if it is solved.
Delay is already back
2024-01-02 10:52:33.768 [TRACE] [nal.protocol.NikoHomeControlDiscover] - bridge discovery response 443B00EF1958C0A80076FFFFFF001902010200120001005B02
2024-01-02 10:52:33.769 [DEBUG] [nal.protocol.NikoHomeControlDiscover] - IP address is {443b00ef1958=/192.168.0.118}, unique ID is 443b00ef1958
2024-01-02 10:52:34.270 [DEBUG] [ikoHomeControlBridgeDiscoveryService] - NHC II bridge found at /192.168.0.118
2024-01-02 10:53:11.061 [DEBUG] [very.NikoHomeControlDiscoveryService] - getting devices on 443b00ef1958
2024-01-02 10:53:34.270 [DEBUG] [ikoHomeControlBridgeDiscoveryService] - discovery broadcast on 192.168.0.255
2024-01-02 10:53:34.274 [TRACE] [nal.protocol.NikoHomeControlDiscover] - bridge discovery response 443B00EF1958C0A80076FFFFFF001902010200120001005B02
2024-01-02 10:53:34.274 [DEBUG] [nal.protocol.NikoHomeControlDiscover] - IP address is {443b00ef1958=/192.168.0.118}, unique ID is 443b00ef1958
2024-01-02 10:53:34.775 [DEBUG] [ikoHomeControlBridgeDiscoveryService] - NHC II bridge found at /192.168.0.118
2024-01-02 10:54:10.770 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to '192.168.0.248'. Next attempt in 60000ms
2024-01-02 10:54:10.772 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to '192.168.0.248' with clientid 6af79180-fc9c-48e8-9c4c-96f1ff3269a0
2024-01-02 10:54:11.066 [DEBUG] [very.NikoHomeControlDiscoveryService] - getting devices on 443b00ef1958
2024-01-02 10:54:34.776 [DEBUG] [ikoHomeControlBridgeDiscoveryService] - discovery broadcast on 192.168.0.255
2024-01-02 10:54:34.779 [TRACE] [nal.protocol.NikoHomeControlDiscover] - bridge discovery response 443B00EF1958C0A80076FFFFFF001902010200120001005B02
2024-01-02 10:54:34.780 [DEBUG] [nal.protocol.NikoHomeControlDiscover] - IP address is {443b00ef1958=/192.168.0.118}, unique ID is 443b00ef1958
2024-01-02 10:54:35.280 [DEBUG] [ikoHomeControlBridgeDiscoveryService] - NHC II bridge found at /192.168.0.118
2024-01-02 10:55:00.011 [INFO ] [l.googletv.GoogleTVConnectionManager] - D45EEC72852F - Error opening SSL connection to 192.168.0.106:6467 Connection timed out
2024-01-02 10:55:11.070 [DEBUG] [very.NikoHomeControlDiscoveryService] - getting devices on 443b00ef1958
2024-01-02 10:55:26.206 [DEBUG] [handler.NikoHomeControlActionHandler] - handle command 0 for nikohomecontrol:dimmer:443b00ef1958:ea1a834e-da0f-47ee-9122-e13b9d007eac:brightness
2024-01-02 10:55:26.206 [DEBUG] [ol.internal.protocol.nhc2.NhcAction2] - execute action Off of type DIMMER for ea1a834e-da0f-47ee-9122-e13b9d007eac
2024-01-02 10:55:26.207 [DEBUG] [nal.protocol.nhc2.NhcMqttConnection2] - connection state CONNECTED for 192_168_0_251-nikohomecontrol_bridge2_443b00ef1958
2024-01-02 10:55:26.207 [DEBUG] [nal.protocol.nhc2.NhcMqttConnection2] - publish hobby/control/devices/cmd, {"Method":"devices.control","ErrCode":"","ErrMessage":"","Params":[{"Devices":[{"Name":"","Uuid":"ea1a834e-da0f-47ee-9122-e13b9d007eac","Technology":"","Identifier":"","Model":"","Type":"","Online":"","Properties":[{"Status":"Off"}]}]}]}
2024-01-02 10:55:26.211 [TRACE] [l.nhc2.NikoHomeControlCommunication2] - not acted on received message topic hobby/control/devices/cmd, payload {"Method":"devices.control","ErrCode":"","ErrMessage":"","Params":[{"Devices":[{"Name":"","Uuid":"ea1a834e-da0f-47ee-9122-e13b9d007eac","Technology":"","Identifier":"","Model":"","Type":"","Online":"","Properties":[{"Status":"Off"}]}]}]}
2024-01-02 10:55:26.403 [TRACE] [l.nhc2.NikoHomeControlCommunication2] - received topic hobby/control/devices/evt, payload {"Params":[{"Devices":[{"Uuid":"ea1a834e-da0f-47ee-9122-e13b9d007eac","Properties":[{"Status":"Off"}]}]}],"Method":"devices.status"}
2024-01-02 10:55:26.404 [DEBUG] [econtrol.internal.protocol.NhcAction] - update channel state for ea1a834e-da0f-47ee-9122-e13b9d007eac with 0
2024-01-02 10:55:26.404 [DEBUG] [l.nhc2.NikoHomeControlCommunication2] - setting action ea1a834e-da0f-47ee-9122-e13b9d007eac internally to OFF
2024-01-02 10:55:35.281 [DEBUG] [ikoHomeControlBridgeDiscoveryService] - discovery broadcast on 192.168.0.255
2024-01-02 10:55:35.284 [TRACE] [nal.protocol.NikoHomeControlDiscover] - bridge discovery response 443B00EF1958C0A80076FFFFFF001902010200120001005B02
2024-01-02 10:55:35.285 [DEBUG] [nal.protocol.NikoHomeControlDiscover] - IP address is {443b00ef1958=/192.168.0.118}, unique ID is 443b00ef1958
2024-01-02 10:55:35.786 [DEBUG] [ikoHomeControlBridgeDiscoveryService] - NHC II bridge found at /192.168.0.118
Can you check the setting for refresh interval on the bridge and set it to 0 if not the case already?
I see in the log it is trying to reconnect to the bridge, and times out. It then waits before trying again. That delay also delays the execution of the command.
I know I have done some improvements to this in a PR that has not yet been merged. However, I am still running the version in the distro myself, with refresh interval set to 0, and I don’t have the issue.
I also noticed that but changing the refresh interval is simply doing nothing.
I mean, if it is set to 300, 100 or 0 It is still doing the discovery;
It is not about the discovery. That will always happen, but has no impact on reconnecting.
My worry was this line:
2024-01-02 10:54:10.770 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to '192.168.0.248'. Next attempt in 60000ms
This is actually a message of the mqtt broker the binding is using underneath, not directly from the binding. It looks like it is losing an mqtt connection and failing to recreate it.
Setting the refresh to 0 may have an impact on this.
That is an error to another mqtt broker that is not online at the moment
Sorry, bad reading from my side.
Interesting though. Could you try to disable the mqtt thing that uses that broker? I am wondering if mqtt is hanging because it is stuck in a waiting loop for something else.
Apart from that, the sequence of events (handle command, send to NHC, get response) is all happening in 200 ms.
So is the delay before or after this sequence of events? I can’t see that in the log. You would need the event log next to this.
Here is some more detailed log.
First line when I switched on the Item, last line when it actually swiiches on the light, takes about 50 seconds now.
12:57:20.181 [INFO ] [openhab.event.ItemCommandEvent ] - Item 'Lichteetkamer_Brightness' received command 33
12:57:20.182 [INFO ] [openhab.event.ItemStatePredictedEvent] - Item 'Lichteetkamer_Brightness' predicted to become 33
12:57:20.182 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Lichteetkamer_Brightness' updated to 33
12:57:20.182 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'Lichteetkamer_Brightness' changed from 0 to 33
12:57:24.220 [DEBUG] [NikoHomeControlBridgeDiscoveryService] - discovery broadcast on 192.168.0.255
12:57:24.224 [DEBUG] [rnal.protocol.NikoHomeControlDiscover] - IP address is {443b00ef1958=/192.168.0.118}, unique ID is 443b00ef1958
12:57:24.725 [DEBUG] [NikoHomeControlBridgeDiscoveryService] - NHC II bridge found at /192.168.0.118
12:57:40.079 [DEBUG] [overy.NikoHomeControlDiscoveryService] - getting devices on 443b00ef1958
12:58:10.224 [DEBUG] [.handler.NikoHomeControlActionHandler] - handle command 33 for nikohomecontrol:dimmer:443b00ef1958:ea1a834e-da0f-47ee-9122-e13b9d007eac:brightness
12:58:10.224 [DEBUG] [rol.internal.protocol.nhc2.NhcAction2] - execute action 33 of type DIMMER for ea1a834e-da0f-47ee-9122-e13b9d007eac
12:58:10.224 [DEBUG] [mecontrol.internal.protocol.NhcAction] - update channel state for ea1a834e-da0f-47ee-9122-e13b9d007eac with 33
12:58:10.225 [DEBUG] [rnal.protocol.nhc2.NhcMqttConnection2] - connection state CONNECTED for 192_168_0_251-nikohomecontrol_bridge2_443b00ef1958
12:58:10.225 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Lichteetkamer_Brightness' updated to 33
12:58:10.225 [DEBUG] [rnal.protocol.nhc2.NhcMqttConnection2] - publish hobby/control/devices/cmd, {"Method":"devices.control","ErrCode":"","ErrMessage":"","Params":[{"Devices":[{"Name":"","Uuid":"ea1a834e-da0f-47ee-9122-e13b9d007eac","Technology":"","Identifier":"","Model":"","Type":"","Online":"","Properties":[{"Status":"On"}]}]}]}
12:58:10.226 [DEBUG] [rnal.protocol.nhc2.NhcMqttConnection2] - connection state CONNECTED for 192_168_0_251-nikohomecontrol_bridge2_443b00ef1958
12:58:10.226 [DEBUG] [rnal.protocol.nhc2.NhcMqttConnection2] - publish hobby/control/devices/cmd, {"Method":"devices.control","ErrCode":"","ErrMessage":"","Params":[{"Devices":[{"Name":"","Uuid":"ea1a834e-da0f-47ee-9122-e13b9d007eac","Technology":"","Identifier":"","Model":"","Type":"","Online":"","Properties":[{"Brightness":"33"}]}]}]}
12:58:10.341 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'BoschActual_boschSettemp' updated to 21.5
12:58:10.429 [DEBUG] [mecontrol.internal.protocol.NhcAction] - update channel state for eaf30e72-5d82-4602-b996-d974e729b6e9 with 0
12:58:10.429 [DEBUG] [ol.nhc2.NikoHomeControlCommunication2] - setting action eaf30e72-5d82-4602-b996-d974e729b6e9 internally to OFF
12:58:10.429 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'AllesUit' updated to OFF
12:58:10.430 [DEBUG] [mecontrol.internal.protocol.NhcAction] - update channel state for ea1a834e-da0f-47ee-9122-e13b9d007eac with 33
12:58:10.430 [INFO ] [openhab.event.ItemStateChangedEvent ] - Item 'AllesUit' changed from ON to OFF
12:58:10.430 [DEBUG] [ol.nhc2.NikoHomeControlCommunication2] - setting action ea1a834e-da0f-47ee-9122-e13b9d007eac internally to 33
12:58:10.430 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Lichteetkamer_Brightness' updated to 33
12:58:10.430 [DEBUG] [mecontrol.internal.protocol.NhcAction] - update channel state for ea1a834e-da0f-47ee-9122-e13b9d007eac with 33
12:58:10.431 [DEBUG] [ol.nhc2.NikoHomeControlCommunication2] - setting action ea1a834e-da0f-47ee-9122-e13b9d007eac internally to ON
12:58:10.431 [INFO ] [openhab.event.ItemStateUpdatedEvent ] - Item 'Lichteetkamer_Brightness' updated to 33
I think I solved it.
I disabled all my things and re-enabled them one by one. Now the delay looks gone.
Strange thing is that I have all my things enabled again as it was before. The Niko binding was the only one which had an issue. All other bindings and even other mqtt things were not having a problem.
Let’s hope it stays like this.