openHAB is running on a docker Host with static IP (sharing IP with docker host) and I can not confirm that it has something to do with my router. My internet connection is up since dec 27th according to my router.
I had a look at my crontab to see what happens at 0 oâclock every night and I was updating another docker container. So I just tried again and it seems that whenever a docker container is started HomeKit bridge is reacting on network interface changes and the plugin stops working.
very interesting investigation.
make it reproducible is the first step to find a solution for it.
i checked the homekit addon code for this and it is really simple and straightforward - remove interfaces from mDNS that were reported as down and add interfaces reported as up. no complex logic and checks.
one thing i could think of, if it happens to quick and we get notification in wrong order, first ânew interface upâ and then âinterface downâ, then it would remove it but dont add it again.
please also check log files for these messages
âstart HomeKit bridgeâ
âstop HomeKit bridgeâ
could you please set log level for this package to TRACE and see whether we get more information
1/ unpowered the router and power it again
2/ after reconnection the hap serivce is lost
deamon.log
Jan 3 13:59:44 raspberrypi dhcpcd[596]: wlan0: carrier lost
Jan 3 13:59:44 raspberrypi systemd-networkd[420]: wlan0: Lost carrier
Jan 3 13:59:44 raspberrypi avahi-daemon[406]: Withdrawing address record for 192.168.0.13 on wlan0.
Jan 3 13:59:44 raspberrypi avahi-daemon[406]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.13.
Jan 3 13:59:44 raspberrypi avahi-daemon[406]: Interface wlan0.IPv4 no longer relevant for mDNS.
Jan 3 13:59:44 raspberrypi dhcpcd[596]: wlan0: deleting route to 192.168.0.0/24
Jan 3 13:59:44 raspberrypi dhcpcd[596]: wlan0: deleting default route via 192.168.0.1
Jan 3 14:00:45 raspberrypi ddclient[686]: WARNING: cannot connect to checkip.dyndns.org:80 socket: IO::Socket::INET: Bad hostname 'checkip.dyndns.org'
Jan 3 14:01:05 raspberrypi dhcpcd[596]: wlan0: carrier acquired
Jan 3 14:01:05 raspberrypi systemd-networkd[420]: wlan0: Gained carrier
Jan 3 14:01:05 raspberrypi dhcpcd[596]: wlan0: IAID 32:53:48:e2
Jan 3 14:01:05 raspberrypi dhcpcd[596]: wlan0: probing address 192.168.0.13/24
Jan 3 14:01:06 raspberrypi dhcpcd[596]: wlan0: soliciting an IPv6 router
Jan 3 14:01:11 raspberrypi dhcpcd[596]: wlan0: using static address 192.168.0.13/24
Jan 3 14:01:11 raspberrypi avahi-daemon[406]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.13.
Jan 3 14:01:11 raspberrypi avahi-daemon[406]: New relevant interface wlan0.IPv4 for mDNS.
Jan 3 14:01:11 raspberrypi avahi-daemon[406]: Registering new address record for 192.168.0.13 on wlan0.IPv4.
Jan 3 14:01:11 raspberrypi dhcpcd[596]: wlan0: adding route to 192.168.0.0/24
Jan 3 14:01:11 raspberrypi dhcpcd[596]: wlan0: adding default route via 192.168.0.1
Jan 3 14:01:14 raspberrypi systemd[1]: Started Session 2577 of user pi.
Jan 3 14:01:36 raspberrypi systemd[1]: Started Session 2578 of user pi.
Jan 3 14:02:08 raspberrypi systemd-networkd[420]: wlan0: Lost carrier
Jan 3 14:02:08 raspberrypi dhcpcd[596]: wlan0: carrier lost
Jan 3 14:02:08 raspberrypi avahi-daemon[406]: Withdrawing address record for 192.168.0.13 on wlan0.
Jan 3 14:02:08 raspberrypi avahi-daemon[406]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.13.
Jan 3 14:02:08 raspberrypi avahi-daemon[406]: Interface wlan0.IPv4 no longer relevant for mDNS.
Jan 3 14:02:08 raspberrypi dhcpcd[596]: wlan0: deleting route to 192.168.0.0/24
Jan 3 14:02:08 raspberrypi dhcpcd[596]: wlan0: deleting default route via 192.168.0.1
Jan 3 14:02:46 raspberrypi dhcpcd[596]: wlan0: carrier acquired
Jan 3 14:02:46 raspberrypi systemd-networkd[420]: wlan0: Gained carrier
Jan 3 14:02:46 raspberrypi dhcpcd[596]: wlan0: IAID 32:53:48:e2
Jan 3 14:02:46 raspberrypi dhcpcd[596]: wlan0: probing address 192.168.0.13/24
Jan 3 14:02:47 raspberrypi dhcpcd[596]: wlan0: soliciting an IPv6 router
Jan 3 14:02:51 raspberrypi dhcpcd[596]: wlan0: using static address 192.168.0.13/24
Jan 3 14:02:51 raspberrypi avahi-daemon[406]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.13.
Jan 3 14:02:51 raspberrypi avahi-daemon[406]: New relevant interface wlan0.IPv4 for mDNS.
Jan 3 14:02:51 raspberrypi dhcpcd[596]: wlan0: adding route to 192.168.0.0/24
Jan 3 14:02:51 raspberrypi avahi-daemon[406]: Registering new address record for 192.168.0.13 on wlan0.IPv4.
Jan 3 14:02:51 raspberrypi dhcpcd[596]: wlan0: adding default route via 192.168.0.1
Jan 3 14:03:14 raspberrypi systemd[1]: Started Session 2579 of user pi.
openhab.log
2023-01-03 13:59:50.263 [WARN ] [io.openhabcloud.internal.CloudClient] - Socket.IO disconnected: ping timeout
2023-01-03 13:59:50.267 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = df...6f, base URL = http://localhost:8080)
2023-01-03 14:00:07.611 [DEBUG] [org.openhab.core.net.NetUtil ] - added 0 network interfaces: []
2023-01-03 14:00:07.612 [DEBUG] [org.openhab.core.net.NetUtil ] - removed 1 network interfaces: [192.168.0.13/24]
2023-01-03 14:00:07.617 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.
2023-01-03 14:01:05.906 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'mqtt75.supla.org'. Next attempt in 60000ms
2023-01-03 14:01:05.910 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'mqtt75.supla.org' with clientid 77194c8a-f3e4-48bb-aa35-738eaf37de1f
2023-01-03 14:01:22.633 [DEBUG] [org.openhab.core.net.NetUtil ] - added 1 network interfaces: [192.168.0.13/24]
2023-01-03 14:01:22.634 [DEBUG] [org.openhab.core.net.NetUtil ] - removed 0 network interfaces: []
2023-01-03 14:01:22.642 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.
2023-01-03 14:02:05.915 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'mqtt75.supla.org'. Next attempt in 60000ms
2023-01-03 14:02:05.924 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'mqtt75.supla.org' with clientid 77194c8a-f3e4-48bb-aa35-738eaf37de1f
2023-01-03 14:02:32.672 [DEBUG] [org.openhab.core.net.NetUtil ] - added 0 network interfaces: []
2023-01-03 14:02:32.675 [DEBUG] [org.openhab.core.net.NetUtil ] - removed 1 network interfaces: [192.168.0.13/24]
2023-01-03 14:02:32.683 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.
2023-01-03 14:02:53.344 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = df...6f, base URL = http://localhost:8080)
2023-01-03 14:03:05.928 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'mqtt75.supla.org'. Next attempt in 60000ms
2023-01-03 14:03:05.936 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'mqtt75.supla.org' with clientid 77194c8a-f3e4-48bb-aa35-738eaf37de1f
2023-01-03 14:03:47.698 [DEBUG] [org.openhab.core.net.NetUtil ] - added 1 network interfaces: [192.168.0.13/24]
2023-01-03 14:03:47.700 [DEBUG] [org.openhab.core.net.NetUtil ] - removed 0 network interfaces: []
2023-01-03 14:03:47.708 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.
Second try : the same steps hap service lost again. Refreshing the bundle brings back hap.
2023-01-03 14:11:19.431 [WARN ] [io.openhabcloud.internal.CloudClient] - Socket.IO disconnected: ping timeout
2023-01-03 14:11:19.434 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = df...6f, base URL = http://localhost:8080)
2023-01-03 14:12:15.837 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'mqtt75.supla.org'. Next attempt in 60000ms
2023-01-03 14:12:15.848 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'mqtt75.supla.org' with clientid 77194c8a-f3e4-48bb-aa35-738eaf37de1f
2023-01-03 14:12:47.748 [DEBUG] [org.openhab.core.net.NetUtil ] - added 0 network interfaces: []
2023-01-03 14:12:47.751 [DEBUG] [org.openhab.core.net.NetUtil ] - removed 1 network interfaces: [192.168.0.13/24]
2023-01-03 14:12:47.759 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.
2023-01-03 14:13:15.850 [INFO ] [.reconnect.PeriodicReconnectStrategy] - Try to restore connection to 'mqtt75.supla.org'. Next attempt in 60000ms
2023-01-03 14:13:15.855 [INFO ] [.transport.mqtt.MqttBrokerConnection] - Starting MQTT broker connection to 'mqtt75.supla.org' with clientid 77194c8a-f3e4-48bb-aa35-738eaf37de1f
2023-01-03 14:13:22.869 [INFO ] [io.openhabcloud.internal.CloudClient] -
Jan 3 14:10:58 raspberrypi systemd-networkd[420]: wlan0: Lost carrier
Jan 3 14:10:58 raspberrypi dhcpcd[596]: wlan0: carrier lost
Jan 3 14:10:58 raspberrypi avahi-daemon[406]: Withdrawing address record for 192.168.0.13 on wlan0.
Jan 3 14:10:58 raspberrypi avahi-daemon[406]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.13.
Jan 3 14:10:58 raspberrypi avahi-daemon[406]: Interface wlan0.IPv4 no longer relevant for mDNS.
Jan 3 14:10:58 raspberrypi dhcpcd[596]: wlan0: deleting route to 192.168.0.0/24
Jan 3 14:10:58 raspberrypi dhcpcd[596]: wlan0: deleting default route via 192.168.0.1
Jan 3 14:11:33 raspberrypi dhcpcd[596]: wlan0: carrier acquired
Jan 3 14:11:33 raspberrypi systemd-networkd[420]: wlan0: Gained carrier
Jan 3 14:11:33 raspberrypi dhcpcd[596]: wlan0: IAID 32:53:48:e2
Jan 3 14:11:33 raspberrypi dhcpcd[596]: wlan0: probing address 192.168.0.13/24
Jan 3 14:11:34 raspberrypi dhcpcd[596]: wlan0: soliciting an IPv6 router
Jan 3 14:11:38 raspberrypi dhcpcd[596]: wlan0: using static address 192.168.0.13/24
Jan 3 14:11:38 raspberrypi avahi-daemon[406]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.13.
Jan 3 14:11:38 raspberrypi avahi-daemon[406]: New relevant interface wlan0.IPv4 for mDNS.
Jan 3 14:11:38 raspberrypi dhcpcd[596]: wlan0: adding route to 192.168.0.0/24
Jan 3 14:11:38 raspberrypi avahi-daemon[406]: Registering new address record for 192.168.0.13 on wlan0.IPv4.
Jan 3 14:11:38 raspberrypi dhcpcd[596]: wlan0: adding default route via 192.168.0.1
Jan 3 14:11:44 raspberrypi systemd[1]: Started Session 2581 of user pi.
Jan 3 14:11:47 raspberrypi systemd[1]: session-2579.scope: Succeeded.
Jan 3 14:12:07 raspberrypi systemd[1]: Started Session 2582 of user pi.
Jan 3 14:12:35 raspberrypi systemd-networkd[420]: wlan0: Lost carrier
Jan 3 14:12:35 raspberrypi dhcpcd[596]: wlan0: carrier lost
Jan 3 14:12:35 raspberrypi avahi-daemon[406]: Withdrawing address record for 192.168.0.13 on wlan0.
Jan 3 14:12:35 raspberrypi avahi-daemon[406]: Leaving mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.13.
Jan 3 14:12:35 raspberrypi avahi-daemon[406]: Interface wlan0.IPv4 no longer relevant for mDNS.
Jan 3 14:12:35 raspberrypi dhcpcd[596]: wlan0: deleting route to 192.168.0.0/24
Jan 3 14:12:35 raspberrypi dhcpcd[596]: wlan0: deleting default route via 192.168.0.1
Jan 3 14:13:08 raspberrypi dhcpcd[596]: wlan0: carrier acquired
Jan 3 14:13:08 raspberrypi systemd-networkd[420]: wlan0: Gained carrier
Jan 3 14:13:08 raspberrypi dhcpcd[596]: wlan0: IAID 32:53:48:e2
Jan 3 14:13:08 raspberrypi dhcpcd[596]: wlan0: probing address 192.168.0.13/24
Jan 3 14:13:09 raspberrypi dhcpcd[596]: wlan0: soliciting an IPv6 router
Jan 3 14:13:13 raspberrypi dhcpcd[596]: wlan0: using static address 192.168.0.13/24
Jan 3 14:13:13 raspberrypi avahi-daemon[406]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.13.
Jan 3 14:13:13 raspberrypi avahi-daemon[406]: New relevant interface wlan0.IPv4 for mDNS.
Jan 3 14:13:13 raspberrypi dhcpcd[596]: wlan0: adding route to 192.168.0.0/24
Jan 3 14:13:13 raspberrypi avahi-daemon[406]: Registering new address record for 192.168.0.13 on wlan0.IPv4.
Jan 3 14:13:13 raspberrypi dhcpcd[596]: wlan0: adding default route via 192.168.0.1
Jan 3 14:13:19 raspberrypi systemd[1]: Started Session 2583 of user pi.
not sure why - but my router has strange startup sequence and devices are connecting and reconnecting 3 times during boot ( host, desktop and other)
in my case it is run from rootâs crontab. Insert it using âsudo crontab -eâ, chmod +x script and it should work.
if you want to do it from normal user - check if you are able to run this command step by step - openhab-cli, avahi-browse.
Weird, I added it to sudo crontab -e as well.
I can run the shell directly using sudo /opt/homeKitWatchdog/homeKitWatchdog.sh
But from crontab its not working.
Heres my crontab entry: */1 * * * * /opt/homeKitWatchdog/homeKitWatchdog.sh >> /var/log/homeKitWatchdog.log
but all my log does is
................................................
2023.01.16 20:51:01
hap service not found restarting
................................................
When running it directly using sudo /opt/homeKitWatchdog/homeKitWatchdog.sh I get
................................................
2023.01.16 20:54:10
hap service not found restarting
Logging in as openhab
................................................
I checked permissions for the shell and the log. But the command is never executed it seemsâŠ
Any idea?
you need to check the homekit bridge name in openhab config. In my setup itâis âopenHABâ try to execute
avahi-browse -t _hap._tcp |grep openHAB and tell me if there is a line if not try avahi-browse -a and find it, then change the grep openHab
As I said, everything works perfectly fine if I execute the shell directly. Just from crontab its behaving different.
I will check the logs and get back to you, thanks again!
So after some weeks my homekit is unavailable again.
Trace writes this message:
18:14:11.662 [TRACE] [enhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.
18:15:13.721 [TRACE] [enhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.
Does your router/access point automatically change channels?
Do you have a mesh WiFI network?
Try disabling and automatic channel changes and/or bind your OpenHAB device to one access point.
I have seen quite a few other pieces of software have issues with the above so it is worth ruling them out as potential issues.
i am âstableâ on 3.4.1 with 9 hosts now, itâs not related to 3.4.1 but the homekit bridge sometimes is down after network changes
@moto you are right, cron is not handling correctly the openhab-cli command which seems to be a wrapper to ssh with password at prompt, switching to rsa-keys is helping. Now we have working solution to refresh it.
@yfre any news from your site ? or / somebody on it ?
it looks like in some case the network change / short reconnect is not handled correctly by homekit addon.
the fix was already implemented by @ccutrer but it is for oh4.0. not sure whether it can be installed on 3.4.1
if 3.4.2 will be release then this fix can be included in 3.4.2
alternative, try to find a way to avoid network changes, e.g. static ip address.
you can try to install the
@yfre@ccutrer 3.4.2 installed MY issue still exist. after powering off and on router again openhab _hap._tcp is not visible in the network and i need to refreash the bundle.
Version: 3.4.2 (Build)
ah now i understand it will be included in 3.4.3 build
Note also if you continue to have problems, try setting Use openHAB mDNS service to off in the HomeKit settings. Iâve found an issue where if your network interfaces change (in my case bringing up a new docker container), openHAB resets mDNS, but the HomeKit addon doesnât know about it.
thank you i will try. I noticed that with toggled ON the âbundle:restart org.openhab.io.homekitâ command used in my cron script is not helping to bring back the mds entry of homekit bridge. So the whole script is not working
btw is openhab 3.4.3 planned to be released? is this fix included in 4.0?