search

openhab / openhab-addons

Add-ons for openHAB
https://www.openhab.org/
Eclipse Public License 2.0
1.88k stars 3.59k forks source link

[HomeKit] Doesn’t start if OH start before network is available #13399

Open grzegorz914 opened 2 years ago

grzegorz914 commented 2 years ago

Some time in my home the power is cycled on/off and after this HomeKit doesn’t start.

Expected Behavior

Always start after power on/off

Current Behavior

I have observed if OH start before my router wake up and the DHCP server is available the HomeKit doesn’t start. Just all devices don’t respond in Home.app. After this need to restart manually OH and all working again fine.

Possible Solution

Automatically restart HomeKit if not start after first run.

Steps to Reproduce (for Bugs)

  1. Power OFF OH server and Home Network.
  2. First start OH server and after some time start Home Network.

Context

I try delay HomeKit start to 60sec but this not fixed this issue.

Your Environment

Kracher019 commented 1 year ago

I‘m facing the same issue on the latest Build (OH 3.4.1 Release Build). From my investigation the issue can be reproduced 100% when restarting the router. _hap._tcp. doesn’t have openHAB advertised anymore. The log (trace) shows „HomeKit bridge reacting on network interface changes.“ after the router is available again. But somehow it doesn’t work.

Restarting the bundle via console fixes the issue (dns advertising and devices are available again)

Also worth noting: the issue „reappeared“ after an upgrade from version (3.3.0 I think?)

lsiepel commented 2 months ago

Since this issue was raised, many homekit pull requests where merged. Me and others had similar problems, but i must say that since a while the homekit binding is getting stable. Can you confirm this issue is still happening with openHAB 4.2.0 or close the issue of that is no longer the case?

grzegorz914 commented 2 months ago

Removed

grzegorz914 commented 2 months ago

Looks like is not fixed, today after power cycle of whole system the HomeKit doesn’t run. I need enable and disable mdns advertiser to start it again.

grzegorz914 commented 2 months ago

Here the whole log what happens after whole system is ON:

2024-07-29 13:01:19.968 [WARN ] [io.openhabcloud.internal.CloudClient] - Error during communication: EngineIOException websocket error
2024-07-29 13:01:19.975 [WARN ] [io.openhabcloud.internal.CloudClient] - Socket.IO disconnected: transport error
2024-07-29 13:01:19.976 [INFO ] [io.openhabcloud.internal.CloudClient] - Disconnected from the openHAB Cloud service (UUID = 1a...d1, base URL = http://localhost:8080)
2024-07-29 13:01:27.585 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.AssertionError: java.net.BindException: Can't assign requested address (setsockopt failed)
    at sun.nio.ch.DatagramChannelImpl.drop(DatagramChannelImpl.java:1727) ~[?:?]
    at sun.nio.ch.MembershipKeyImpl.drop(MembershipKeyImpl.java:147) ~[?:?]
    at sun.nio.ch.DatagramSocketAdaptor.leaveGroup(DatagramSocketAdaptor.java:512) ~[?:?]
    at java.net.DatagramSocket.leaveGroup(DatagramSocket.java:1350) ~[?:?]
    at java.net.MulticastSocket.leaveGroup(MulticastSocket.java:386) ~[?:?]
    at org.jupnp.transport.impl.MulticastReceiverImpl.stop(MulticastReceiverImpl.java:101) ~[?:?]
    at org.jupnp.transport.RouterImpl.disable(RouterImpl.java:171) ~[?:?]
    at org.openhab.core.config.discovery.upnp.internal.UpnpDiscoveryService.lambda$1(UpnpDiscoveryService.java:228) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:317) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[?:?]
    at java.lang.Thread.run(Thread.java:1583) [?:?]
Caused by: java.net.BindException: Can't assign requested address (setsockopt failed)
    at sun.nio.ch.Net.joinOrDrop6(Native Method) ~[?:?]
    at sun.nio.ch.Net.drop6(Net.java:760) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.drop(DatagramChannelImpl.java:1719) ~[?:?]
    ... 13 more
2024-07-29 13:01:41.390 [ERROR] [nternal.simatic.SimaticGenericDevice] - 192.168.1.30 - 
org.openhab.binding.simatic.internal.simatic.SimaticReadException: Read data area error (Area=DB6.DBB14-DB6.DBB182, Return code=0xffffff7d, Error=No data returned. Connection lost?})
    at org.openhab.binding.simatic.internal.simatic.SimaticTCP.readDataArea(SimaticTCP.java:317) ~[?:?]
    at org.openhab.binding.simatic.internal.simatic.SimaticGenericDevice.checkNewData(SimaticGenericDevice.java:402) ~[?:?]
    at org.openhab.binding.simatic.internal.simatic.SimaticGenericDevice.execute(SimaticGenericDevice.java:148) ~[?:?]
    at org.openhab.binding.simatic.internal.simatic.SimaticGenericDevice.lambda$0(SimaticGenericDevice.java:108) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572) ~[?:?]
    at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:358) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:305) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[?:?]
    at java.lang.Thread.run(Thread.java:1583) [?:?]
2024-07-29 13:01:41.394 [INFO ] [nternal.simatic.SimaticGenericDevice] - 192.168.1.30 - Trying to reconnect
2024-07-29 13:01:41.397 [ERROR] [.simatic.internal.simatic.SimaticTCP] - 192.168.1.30 - cannot connect to PLC. Network is unreachable
2024-07-29 13:01:43.633 [INFO ] [nternal.simatic.SimaticGenericDevice] - 192.168.1.30 - Trying to reconnect
2024-07-29 13:01:43.636 [ERROR] [.simatic.internal.simatic.SimaticTCP] - 192.168.1.30 - cannot connect to PLC. Network is unreachable
2024-07-29 13:01:47.626 [INFO ] [nternal.simatic.SimaticGenericDevice] - 192.168.1.30 - Trying to reconnect
2024-07-29 13:01:47.629 [ERROR] [.simatic.internal.simatic.SimaticTCP] - 192.168.1.30 - cannot connect to PLC. Network is unreachable
2024-07-29 13:01:53.564 [INFO ] [nternal.simatic.SimaticGenericDevice] - 192.168.1.30 - Trying to reconnect
2024-07-29 13:01:53.567 [ERROR] [.simatic.internal.simatic.SimaticTCP] - 192.168.1.30 - cannot connect to PLC. Network is unreachable
2024-07-29 13:01:59.643 [INFO ] [nternal.simatic.SimaticGenericDevice] - 192.168.1.30 - Trying to reconnect
2024-07-29 13:01:59.645 [ERROR] [.simatic.internal.simatic.SimaticTCP] - 192.168.1.30 - cannot connect to PLC. Network is unreachable
2024-07-29 13:02:09.614 [INFO ] [nternal.simatic.SimaticGenericDevice] - 192.168.1.30 - Trying to reconnect
2024-07-29 13:02:09.619 [ERROR] [.simatic.internal.simatic.SimaticTCP] - 192.168.1.30 - cannot connect to PLC. Network is unreachable
2024-07-29 13:02:19.635 [INFO ] [nternal.simatic.SimaticGenericDevice] - 192.168.1.30 - Trying to reconnect
2024-07-29 13:02:19.638 [ERROR] [.simatic.internal.simatic.SimaticTCP] - 192.168.1.30 - cannot connect to PLC. Network is unreachable
2024-07-29 13:02:27.753 [WARN ] [org.openhab.core.net.NetUtil        ] - Invalid address '192.168.1.20/24', will use first interface instead.
2024-07-29 13:02:27.759 [WARN ] [org.openhab.core.net.NetUtil        ] - Invalid address '192.168.1.20/24', will use first interface instead.
2024-07-29 13:02:27.764 [WARN ] [org.openhab.core.net.NetUtil        ] - Invalid address '192.168.1.20/24', will use first interface instead.
2024-07-29 13:02:30.569 [INFO ] [nternal.simatic.SimaticGenericDevice] - 192.168.1.30 - Trying to reconnect
2024-07-29 13:02:30.571 [ERROR] [.simatic.internal.simatic.SimaticTCP] - 192.168.1.30 - cannot connect to PLC. Network is unreachable
2024-07-29 13:02:33.559 [WARN ] [istics.impl.base.FloatCharacteristic] - Detected value out of range 102600.0. Returning max value instead. Characteristic io.github.hapjava.characteristics.impl.lightsensor.CurrentAmbientLightLevelCharacteristic@3f59cacd
2024-07-29 13:02:33.580 [INFO ] [mekit.internal.HomekitChangeListener] - Created 115 HomeKit items in instance 1 (no change from prior configuration).
2024-07-29 13:02:33.593 [WARN ] [nhab.io.homekit.internal.HomekitImpl] - could not initialize HomeKit bridge: Can't assign requested address (setsockopt failed)
2024-07-29 13:02:33.598 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.AssertionError: java.net.BindException: Can't assign requested address (setsockopt failed)
    at sun.nio.ch.DatagramChannelImpl.drop(DatagramChannelImpl.java:1727) ~[?:?]
    at sun.nio.ch.MembershipKeyImpl.drop(MembershipKeyImpl.java:147) ~[?:?]
    at sun.nio.ch.DatagramSocketAdaptor.leaveGroup(DatagramSocketAdaptor.java:512) ~[?:?]
    at java.net.DatagramSocket.leaveGroup(DatagramSocket.java:1350) ~[?:?]
    at java.net.MulticastSocket.leaveGroup(MulticastSocket.java:386) ~[?:?]
    at org.jupnp.transport.impl.MulticastReceiverImpl.stop(MulticastReceiverImpl.java:101) ~[?:?]
    at org.jupnp.transport.RouterImpl.disable(RouterImpl.java:171) ~[?:?]
    at org.openhab.core.config.discovery.upnp.internal.UpnpDiscoveryService.lambda$1(UpnpDiscoveryService.java:228) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:317) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[?:?]
    at java.lang.Thread.run(Thread.java:1583) [?:?]
Caused by: java.net.BindException: Can't assign requested address (setsockopt failed)
    at sun.nio.ch.Net.joinOrDrop6(Native Method) ~[?:?]
    at sun.nio.ch.Net.drop6(Net.java:760) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.drop(DatagramChannelImpl.java:1719) ~[?:?]
    ... 13 more
2024-07-29 13:02:44.604 [INFO ] [nternal.simatic.SimaticGenericDevice] - 192.168.1.30 - Trying to reconnect
2024-07-29 13:02:44.608 [ERROR] [.simatic.internal.simatic.SimaticTCP] - 192.168.1.30 - cannot connect to PLC. Network is unreachable
2024-07-29 13:03:00.479 [INFO ] [nternal.simatic.SimaticGenericDevice] - 192.168.1.30 - Trying to reconnect
2024-07-29 13:03:00.482 [ERROR] [.simatic.internal.simatic.SimaticTCP] - 192.168.1.30 - cannot connect to PLC. Network is unreachable
2024-07-29 13:03:17.595 [INFO ] [nternal.simatic.SimaticGenericDevice] - 192.168.1.30 - Trying to reconnect
2024-07-29 13:03:44.439 [INFO ] [.simatic.internal.simatic.SimaticTCP] - 192.168.1.30 - connected. PDU size = 240B
2024-07-29 13:03:48.668 [WARN ] [nhab.io.homekit.internal.HomekitImpl] - trying to start HomeKit server but it is already initialized
2024-07-29 13:03:48.674 [WARN ] [mmon.WrappedScheduledExecutorService] - Scheduled runnable ended with an exception: 
java.lang.AssertionError: java.net.BindException: Can't assign requested address (setsockopt failed)
    at sun.nio.ch.DatagramChannelImpl.drop(DatagramChannelImpl.java:1727) ~[?:?]
    at sun.nio.ch.MembershipKeyImpl.drop(MembershipKeyImpl.java:147) ~[?:?]
    at sun.nio.ch.DatagramSocketAdaptor.leaveGroup(DatagramSocketAdaptor.java:512) ~[?:?]
    at java.net.DatagramSocket.leaveGroup(DatagramSocket.java:1350) ~[?:?]
    at java.net.MulticastSocket.leaveGroup(MulticastSocket.java:386) ~[?:?]
    at org.jupnp.transport.impl.MulticastReceiverImpl.stop(MulticastReceiverImpl.java:101) ~[?:?]
    at org.jupnp.transport.RouterImpl.disable(RouterImpl.java:171) ~[?:?]
    at org.openhab.core.config.discovery.upnp.internal.UpnpDiscoveryService.lambda$1(UpnpDiscoveryService.java:228) ~[?:?]
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:572) ~[?:?]
    at java.util.concurrent.FutureTask.run(FutureTask.java:317) ~[?:?]
    at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1144) ~[?:?]
    at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:642) ~[?:?]
    at java.lang.Thread.run(Thread.java:1583) [?:?]
Caused by: java.net.BindException: Can't assign requested address (setsockopt failed)
    at sun.nio.ch.Net.joinOrDrop6(Native Method) ~[?:?]
    at sun.nio.ch.Net.drop6(Net.java:760) ~[?:?]
    at sun.nio.ch.DatagramChannelImpl.drop(DatagramChannelImpl.java:1719) ~[?:?]
    ... 13 more
2024-07-29 13:06:04.706 [INFO ] [io.openhabcloud.internal.CloudClient] - Connected to the openHAB Cloud service (UUID = 1a...d1, base URL = http://localhost:8080)
2024-07-29 13:06:58.539 [WARN ] [nhab.io.homekit.internal.HomekitImpl] - trying to start HomeKit server but it is already initialized
2024-07-29 13:07:43.780 [WARN ] [rg.openhab.core.io.net.exec.ExecUtil] - Timeout occurred when executing commandLine '[arp, 192.168.1.115]'
2024-07-29 13:07:44.345 [WARN ] [ng.lgwebos.internal.TVControlChannel] - error requesting channel list: 1010 tuner channel map does not exist.
2024-07-29 13:14:59.517 [WARN ] [nhab.io.homekit.internal.HomekitImpl] - trying to start HomeKit server but it is already initialized
2024-07-29 13:17:05.279 [WARN ] [istics.impl.base.FloatCharacteristic] - Detected value out of range 109700.0. Returning max value instead. Characteristic io.github.hapjava.characteristics.impl.lightsensor.CurrentAmbientLightLevelCharacteristic@5e03bf94
2024-07-29 13:17:05.306 [INFO ] [mekit.internal.HomekitChangeListener] - Created 115 HomeKit items in instance 1 (no change from prior configuration).