Docker openHAB 3.2 HomeKit does not start address already in use

robjkamp · February 3, 2022, 10:10pm

Platform information:
- Hardware: AMD EPYC 7282 16-Core Processor/64GiB/Plenty HD space
- OS: Docker on TrueNAS Scale
- Java Runtime Environment: the docker one
- openHAB version: 3.2
Issue of the topic:
Starting the HomeKit bundle fails with the error that the address is already in use
Please post configurations (if applicable):
Standard docker 3.2
If logs where generated please post these here using code fences:

2022-02-03 22:51:49.897 [INFO ] [mekit.internal.HomekitChangeListener] - Created 0 HomeKit items.
2022-02-03 22:51:49.901 [WARN ] [nhab.io.homekit.internal.HomekitImpl] - cannot activate HomeKit binding. Address already in use (Bind failed)
2022-02-03 22:51:49.901 [ERROR] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.2.0 (272)[org.openhab.io.homekit.internal.HomekitImpl(313)] : Error during instantiation of the implementation object java.lang.reflect.InvocationTargetException: null
        at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) ~[?:?]
        at jdk.internal.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) ~[?:?]
        at jdk.internal.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) ~[?:?]
        at java.lang.reflect.Constructor.newInstance(Constructor.java:490) ~[?:?]
        at org.apache.felix.scr.impl.inject.internal.ComponentConstructorImpl.newInstance(ComponentConstructorImpl.java:316) ~[bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.createImplementationObject(SingleComponentManager.java:286) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.createComponent(SingleComponentManager.java:115) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:1000) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:973) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:918) [bundleFile:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:216) [org.eclipse.osgi-3.16.300.jar:?]
        at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:213) [org.eclipse.osgi-3.16.300.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:114) [org.eclipse.osgi-3.16.300.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:48) [org.eclipse.osgi-3.16.300.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:547) [org.eclipse.osgi-3.16.300.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:533) [org.eclipse.osgi-3.16.300.jar:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:656) [org.eclipse.osgi-3.16.300.jar:?]
        at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:88) [bundleFile:?]
        at org.apache.felix.scr.impl.inject.methods.BindMethod.getServiceObject(BindMethod.java:675) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2556) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager$SingleStaticCustomizer.prebind(DependencyManager.java:1398) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager.prebind(DependencyManager.java:1827) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.AbstractComponentManager.collectDependencies(AbstractComponentManager.java:1057) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.getServiceInternal(SingleComponentManager.java:953) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.getService(SingleComponentManager.java:918) [bundleFile:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse$1.run(ServiceFactoryUse.java:216) [org.eclipse.osgi-3.16.300.jar:?]
        at java.security.AccessController.doPrivileged(Native Method) ~[?:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.factoryGetService(ServiceFactoryUse.java:213) [org.eclipse.osgi-3.16.300.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceFactoryUse.getService(ServiceFactoryUse.java:114) [org.eclipse.osgi-3.16.300.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceConsumer$2.getService(ServiceConsumer.java:48) [org.eclipse.osgi-3.16.300.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistrationImpl.getService(ServiceRegistrationImpl.java:547) [org.eclipse.osgi-3.16.300.jar:?]
        at org.eclipse.osgi.internal.serviceregistry.ServiceRegistry.getService(ServiceRegistry.java:533) [org.eclipse.osgi-3.16.300.jar:?]
        at org.eclipse.osgi.internal.framework.BundleContextImpl.getService(BundleContextImpl.java:656) [org.eclipse.osgi-3.16.300.jar:?]
        at org.apache.felix.scr.impl.manager.SingleRefPair.getServiceObject(SingleRefPair.java:88) [bundleFile:?]
        at org.apache.felix.scr.impl.inject.methods.BindMethod.getServiceObject(BindMethod.java:675) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager.getServiceObject(DependencyManager.java:2556) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager.doInvokeBindMethod(DependencyManager.java:2075) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager.invokeBindMethod(DependencyManager.java:2058) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeBindMethod(SingleComponentManager.java:443) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:333) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.DependencyManager$MultipleDynamicCustomizer.addedService(DependencyManager.java:301) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.ServiceTracker$Tracked.customizerAdded(ServiceTracker.java:1200) [bundleFile:?]

robjkamp · February 3, 2022, 10:15pm

This is the bundle info

org.openhab.io.homekit_3.2.0 [272] provides:
--------------------------------------------
osgi.wiring.bundle; org.openhab.io.homekit 3.2.0 [UNUSED]
osgi.wiring.host; org.openhab.io.homekit 3.2.0 [UNUSED]
osgi.identity; org.openhab.io.homekit 3.2.0 [UNUSED]
osgi.wiring.package; org.openhab.io.homekit 3.2.0 [UNUSED]
osgi.service; objectClass:List<String>="org.openhab.core.io.console.extensions.ConsoleCommandExtension"; uses:="org.openhab.core.io.console.extensions" [UNUSED]
osgi.service; objectClass:List<String>="org.openhab.io.homekit.Homekit"; uses:="org.openhab.io.homekit" [UNUSED]
service; [org.osgi.service.cm.ManagedService] with properties:
   service.id = 518
   service.bundleid = 272
   service.scope = singleton
service; [org.openhab.io.homekit.Homekit] with properties:
   port = 9124
   qrCode = X-HM://001408XXEGUWF
   service.id = 519
   service.bundleid = 272
   service.scope = bundle
   component.name = org.openhab.io.homekit.internal.HomekitImpl
   service.config.label = HomeKit Integration
   component.id = 319
   service.config.factory = false
   setupId = GUWF
   useOHmDNS = true
   networkInterface = 192.168.1.199
   service.config.category = io
   service.config.description.uri = io:homekit
   service.pid = [org.openhab.homekit, org.openhab.homekit]
service; [org.openhab.core.io.console.extensions.ConsoleCommandExtension] with properties:
   service.id = 520
   service.bundleid = 272
   service.scope = bundle
   component.name = org.openhab.io.homekit.internal.HomekitCommandExtension
   component.id = 318

rlkoshak · February 3, 2022, 10:15pm

Something else on your machine is up and running at the same port that the Homkit binding wants to use. The docs mentions 9124.

robjkamp · February 3, 2022, 10:18pm

If I change the port to 19124 it throws the same error.

robjkamp · February 4, 2022, 8:25am

No result for

netstat -tulpn

when looking for a port in use

sudo netstat -tulpn | grep tcp
tcp        0      0 127.0.0.1:10248         0.0.0.0:*               LISTEN      11356/k3s server
tcp        0      0 127.0.0.1:10251         0.0.0.0:*               LISTEN      11356/k3s server
tcp        0      0 127.0.0.1:9004          0.0.0.0:*               LISTEN      1691400/RAATServer
tcp        0      0 127.0.0.1:10252         0.0.0.0:*               LISTEN      11356/k3s server
tcp        0      0 127.0.0.1:6444          0.0.0.0:*               LISTEN      11356/k3s server
tcp        0      0 172.16.0.1:5357         0.0.0.0:*               LISTEN      11056/python3
tcp        0      0 172.17.0.10:5357        0.0.0.0:*               LISTEN      11056/python3
tcp        0      0 172.17.193.2:5357       0.0.0.0:*               LISTEN      11056/python3
tcp        0      0 172.17.47.50:5357       0.0.0.0:*               LISTEN      11056/python3
tcp        0      0 172.17.0.1:5357         0.0.0.0:*               LISTEN      11056/python3
tcp        0      0 172.17.39.238:5357      0.0.0.0:*               LISTEN      11056/python3
tcp        0      0 172.17.135.61:5357      0.0.0.0:*               LISTEN      11056/python3
tcp        0      0 169.254.3.1:5357        0.0.0.0:*               LISTEN      11056/python3
tcp        0      0 192.168.1.200:5357      0.0.0.0:*               LISTEN      11056/python3
tcp        0      0 192.168.1.199:5357      0.0.0.0:*               LISTEN      11056/python3
tcp        0      0 0.0.0.0:111             0.0.0.0:*               LISTEN      1/init
tcp        0      0 0.0.0.0:9200            0.0.0.0:*               LISTEN      1691400/RAATServer
tcp        0      0 0.0.0.0:80              0.0.0.0:*               LISTEN      8367/nginx: master
tcp        0      0 0.0.0.0:6000            0.0.0.0:*               LISTEN      1268/middlewared
tcp        0      0 169.254.3.1:39089       0.0.0.0:*               LISTEN      1691188/RoonApplian
tcp        0      0 127.0.0.1:37841         0.0.0.0:*               LISTEN      11356/k3s server
tcp        0      0 0.0.0.0:9330            0.0.0.0:*               LISTEN      1691188/RoonApplian
tcp        0      0 0.0.0.0:9331            0.0.0.0:*               LISTEN      1691188/RoonApplian
tcp        0      0 192.168.1.199:179       0.0.0.0:*               LISTEN      14166/kube-router
tcp        0      0 0.0.0.0:9332            0.0.0.0:*               LISTEN      1691188/RoonApplian
tcp        0      0 0.0.0.0:22              0.0.0.0:*               LISTEN      8351/sshd: /usr/sbi
tcp        0      0 127.0.0.1:42937         0.0.0.0:*               LISTEN      1691111/RoonServer
tcp        0      0 0.0.0.0:443             0.0.0.0:*               LISTEN      8367/nginx: master
tcp        0      0 0.0.0.0:9150            0.0.0.0:*               LISTEN      1691188/RoonApplian
tcp        0      0 127.0.0.1:50051         0.0.0.0:*               LISTEN      14166/kube-router
tcp        0      0 192.168.1.199:50051     0.0.0.0:*               LISTEN      14166/kube-router
tcp6       0      0 127.0.0.1:8101          :::*                    LISTEN      1720148/java
tcp6       0      0 127.0.0.1:35269         :::*                    LISTEN      1720148/java
tcp6       0      0 :::10250                :::*                    LISTEN      11356/k3s server
tcp6       0      0 :::6443                 :::*                    LISTEN      11356/k3s server
tcp6       0      0 fe80::b23a:f2ff:fe:5357 :::*                    LISTEN      11056/python3
tcp6       0      0 fe80::3eec:efff:fe:5357 :::*                    LISTEN      11056/python3
tcp6       0      0 fe80::3eec:efff:fe:5357 :::*                    LISTEN      11056/python3
tcp6       0      0 :::5007                 :::*                    LISTEN      1720148/java
tcp6       0      0 :::111                  :::*                    LISTEN      1/init
tcp6       0      0 :::8080                 :::*                    LISTEN      1720148/java
tcp6       0      0 :::80                   :::*                    LISTEN      8367/nginx: master
tcp6       0      0 ::1:179                 :::*                    LISTEN      14166/kube-router
tcp6       0      0 :::20244                :::*                    LISTEN      14166/kube-router
tcp6       0      0 :::22                   :::*                    LISTEN      8351/sshd: /usr/sbi
tcp6       0      0 :::8443                 :::*                    LISTEN      1720148/java
tcp6       0      0 :::443                  :::*                    LISTEN      8367/nginx: master```

rlkoshak · February 4, 2022, 2:20pm

I don’t use HomeKit so I can’t really be of any further help except to reiterate that a “Bind failed” error means that OH tried to grab a port something else on the machine is already listening on. And the error is coming from the HomeKit binding.

mspl · May 11, 2022, 9:44pm

Looking at my stack trace from a similar error, it seems like the HAP-Java dependency is using jmdns and trying to open the zeroconf multicast port 5353, conflicting with an existing mDNS server, which in my case is Avahi, necessary for Samba. Still looking into how to proceed from here.