Homekit stops working after some hours. openhab 3.4.0

Hi,
I have the same issue and see the following log entries:

2022-12-30 00:01:53.680 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.
2022-12-30 00:04:01.953 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.
2022-12-31 00:02:09.312 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.
2022-12-31 00:05:17.535 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.
2023-01-01 00:02:25.036 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.
2023-01-01 00:04:33.250 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.

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

log:set TRACE org.openhab.core.net

i think i cached this:

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)

I have the same issue, thx for the script. I am having troubles getting it to work in a crontab environment


Did you use the sudo crontab or the regular one?
Any permission changes for the shell?

Thx!

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.

Thanks for your quick reply!

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

i think the command is executed properly, but the hap service is not up - maybe there is an error in configuration ? check the logs of homekit binding

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!

I did setup ssh with an rsa key (Tutorial: Restart Binding from rule - #14 by shutterfreak) to execute the karaf command.

I adapted the shell to execute

ssh -p 8101 -i ~/.ssh/karaf.id_rsa openhab@localhost 'bundle:restart org.openhab.io.homekit'

now its working fine
 who knows what was the reason

Thanks again for your help!

1 Like

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.

IP hasnt changed.

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.

Hi together. I have the same issue, but on 3.4.1.

Pairing works fine, but after ~1 oder ~2 hours there is no connection anymore


Befor the update everything works fine, so it looks like an issue in the 3.4.1 version? I made all the things above


More ideas?!

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 ?

@Jacek_Kaczmarczyk @xtoasty

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

2 Likes

@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 :frowning:

btw is openhab 3.4.3 planned to be released? is this fix included in 4.0?

@Kai is there any chance to get 3.4.3 soon ?