Homekit stops working after some hours. openhab 3.4.0

Slash200 · December 25, 2022, 10:23pm

Hello,

I have the problem that the homekit binding stops working every day after several hours. Only a openhab restart can solve the problem. Log:display | grep homekit shows no errors.
Any ideas where to search for the problem?
Openhab version is 3.4.0

IPv6 is disabled

regards

Tim_Harper · December 26, 2022, 12:31am

Hi! That’s unusual, I’ve been running the Homekit 3.4.0 and it’s been running fine for several days in a row.

Possibly you hit a deadlock scenario? I’d start with getting a thread dump. Send a kill -3 signal to the jvm process running OpenHab, and then find the stack trace (if started with systemd, journalctl -xefu openhab). If there are any threads stuck in the homekit addon, that’d be a good clue.

You could also try bisecting your config. Comment out half of your homekit metadata, if the problem stays, uncomment and comment out the other half, then narrow in, etc.

Tim_Harper · December 26, 2022, 1:30am

More helpful, the Karaf console provides a command dev:dump-create which will export a zip file, which contains threads plus a few other things.

yfre · December 26, 2022, 12:30pm

please also check with discover app whether you see openHAB in mDNS as described here

if you dont see it there, try to change the setting for mDNS service in homekit settings.

Slash200 · December 26, 2022, 4:50pm

HelloEugen,

it is not visible in Discovery app under _hap._tcp
But after a restart with bundle:restart org.openhab.io.homekit it is visible. Also with disabled mDNS toggle in Homekit settings… strange. But I will try it with activated mDNS toggle and will report.
thanks for your help!

Slash200 · December 26, 2022, 10:25pm

So After 6 Hours the Connection is gone. DNS Entry for _hap._tcp. Is Not found. Bundle homekit is Running. Can PiHole cause this Problem?

yfre · December 27, 2022, 9:52am

it is not completely clear what is the root cause for mDNS issues, maybe there are multiple root causes.
few check questions:

is openhab entry “_openhab-server._tcp” also missing in discover app?
if you see _openhab-server._tcp but no _hap._tcp, then it is clear an issue with homekit addon. if both disapper then it is often an issue with network connection of the server
are you running openHAB in a docker container?
could it be that the network connection get interrupted for a short time?
if not done yet, assigned static IP address to openHAB server
if IP address filled in the homekit settings, remove it (make field empty) and check whether it helps

gd35 · December 27, 2022, 1:40pm

I shared the same experience as described by @slash200. Before 3.4.0, my system was based on 3.4.0.M2 (docker container on a synology) and Homekit was pretty stable. Since the upgrade, I lost the connection after a couple of days. I changed the homekit setup by using the openHAB mDNS service. I then executed the following command using the karaf console to restart Homekit: “bundle:restart org.openhab.io.homekit”. Then Homekit works again as before. I will see how many hours/days it will remain ok.

yfre · December 27, 2022, 2:31pm

we have not changed anything in that area between 3.4.0M2 and 3.4.0.
please enable trace logging for homekit with karaf command

log:set TRACE org.openhab.io.homekit.internal

and check log files, once mDNS disappears again for messages like
“HomeKit bridge reacting on network interface changes.”
“removed interface”

Slash200 · December 28, 2022, 2:20pm

Hello eugen,
no it isnt even working after restarting the bundle. Here is the output von log:

15:16:07.344 [TRACE] [enhab.io.homekit.internal.HomekitImpl] - start HomeKit bridge
15:16:07.347 [TRACE] [enhab.io.homekit.internal.HomekitImpl] - suitable mDNS client for IP /192.168.178.44 found and will be used for HomeKit
15:16:07.506 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(328)] : getting activate: activate
15:16:07.508 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(328)] : Locating method activate in class org.openhab.io.homekit.internal.HomekitImpl
15:16:07.509 [TRACE] [mpl.http.impl.NettyHomekitHttpService] - Bound homekit listener to /192.168.178.44:9123
15:16:07.510 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(328)] : Declared Method org.openhab.io.homekit.internal.HomekitImpl.activate([interface org.osgi.service.component.ComponentContext]) not found
15:16:07.511 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(328)] : Locating method activate in class java.lang.Object
15:16:07.512 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(328)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
15:16:07.513 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(328)] : activate method [activate] not found, ignoring
15:16:07.514 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(328)] : Set implementation object for component
15:16:07.515 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(328)] : Changed state from satisfied to active
15:16:07.516 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : This thread collected dependencies
15:16:07.517 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : getService (single component manager) dependencies collected.
15:16:07.518 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : Querying state satisfied
15:16:07.518 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : Querying state satisfied
15:16:07.519 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : For dependency Homekit, optional: false; to bind: [[RefPair: ref: [{org.openhab.io.homekit.Homekit}={port=9123, qrCode=X-HM://001408XXIFMDB, service.id=514, service.bundleid=250, service.scope=bundle, component.name=org.openhab.io.homekit.internal.HomekitImpl, service.config.label=HomeKit Integration, component.id=328, service.config.factory=false, pin=031-45-158, setupId=FMDB, useOHmDNS=true, service.config.category=io, service.config.description.uri=io:homekit, service.pid=[org.openhab.homekit, org.openhab.homekit]}] service: [org.openhab.io.homekit.internal.HomekitImpl@696f0e]]]
15:16:07.520 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : invoking bind: setHomekit: parameters [org.openhab.io.homekit.internal.HomekitImpl]
15:16:07.521 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : invoked bind: setHomekit
15:16:07.522 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : getting activate: activate
15:16:07.523 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : Locating method activate in class org.openhab.io.homekit.internal.HomekitCommandExtension
15:16:07.523 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : Declared Method org.openhab.io.homekit.internal.HomekitCommandExtension.activate([interface org.osgi.service.component.ComponentContext]) not found
15:16:07.524 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : Locating method activate in class org.openhab.core.io.console.extensions.AbstractConsoleCommandExtension
15:16:07.525 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : Declared Method org.openhab.core.io.console.extensions.AbstractConsoleCommandExtension.activate([interface org.osgi.service.component.ComponentContext]) not found
15:16:07.526 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : Locating method activate in class java.lang.Object
15:16:07.527 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
15:16:07.528 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : activate method [activate] not found, ignoring
15:16:07.529 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : Set implementation object for component
15:16:07.530 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : Changed state from satisfied to active
15:16:07.532 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(327)] : dm Homekit tracking 1 SingleStatic added {org.openhab.io.homekit.Homekit}={port=9123, qrCode=X-HM://001408XXIFMDB, service.id=514, service.bundleid=250, service.scope=bundle, component.name=org.openhab.io.homekit.internal.HomekitImpl, service.config.label=HomeKit Integration, component.id=328, service.config.factory=false, pin=031-45-158, setupId=FMDB, useOHmDNS=true, service.config.category=io, service.config.description.uri=io:homekit, service.pid=[org.openhab.homekit, org.openhab.homekit]} (exit)

The IPv4 is the correct one. There is no mDNS anouncement visible

Use openHAB mDNS service is true

With Use openHAB mDNS service is false the mDNS anouncement is back. Output on Log is the following:

15:20:40.514 [TRACE] [enhab.io.homekit.internal.HomekitImpl] - start HomeKit bridge
15:20:40.517 [TRACE] [enhab.io.homekit.internal.HomekitImpl] - create HomeKit server with dedicated mDNS server
15:20:40.706 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(330)] : getting activate: activate
15:20:40.708 [TRACE] [mpl.http.impl.NettyHomekitHttpService] - Bound homekit listener to /192.168.178.44:9123
15:20:40.708 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(330)] : Locating method activate in class org.openhab.io.homekit.internal.HomekitImpl
15:20:40.710 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(330)] : Declared Method org.openhab.io.homekit.internal.HomekitImpl.activate([interface org.osgi.service.component.ComponentContext]) not found
15:20:40.711 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(330)] : Locating method activate in class java.lang.Object
15:20:40.712 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(330)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
15:20:40.714 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(330)] : activate method [activate] not found, ignoring
15:20:40.715 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(330)] : Set implementation object for component
15:20:40.716 [DEBUG] [enhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitImpl(330)] : Changed state from satisfied to active
15:20:40.717 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : This thread collected dependencies
15:20:40.718 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : getService (single component manager) dependencies collected.
15:20:40.719 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : Querying state satisfied
15:20:40.719 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : Querying state satisfied
15:20:40.720 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : For dependency Homekit, optional: false; to bind: [[RefPair: ref: [{org.openhab.io.homekit.Homekit}={port=9123, qrCode=X-HM://001408XXIFMDB, service.id=517, service.bundleid=250, service.scope=bundle, component.name=org.openhab.io.homekit.internal.HomekitImpl, service.config.label=HomeKit Integration, component.id=330, service.config.factory=false, pin=031-45-158, setupId=FMDB, useOHmDNS=false, service.config.category=io, service.config.description.uri=io:homekit, service.pid=[org.openhab.homekit, org.openhab.homekit]}] service: [org.openhab.io.homekit.internal.HomekitImpl@2f5b41]]]
15:20:40.721 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : invoking bind: setHomekit: parameters [org.openhab.io.homekit.internal.HomekitImpl]
15:20:40.722 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : invoked bind: setHomekit
15:20:40.723 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : getting activate: activate
15:20:40.724 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : Locating method activate in class org.openhab.io.homekit.internal.HomekitCommandExtension
15:20:40.725 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : Declared Method org.openhab.io.homekit.internal.HomekitCommandExtension.activate([interface org.osgi.service.component.ComponentContext]) not found
15:20:40.726 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : Locating method activate in class org.openhab.core.io.console.extensions.AbstractConsoleCommandExtension
15:20:40.727 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : Declared Method org.openhab.core.io.console.extensions.AbstractConsoleCommandExtension.activate([interface org.osgi.service.component.ComponentContext]) not found
15:20:40.728 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : Locating method activate in class java.lang.Object
15:20:40.729 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
15:20:40.730 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : activate method [activate] not found, ignoring
15:20:40.731 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : Set implementation object for component
15:20:40.732 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : Changed state from satisfied to active
15:20:40.734 [DEBUG] [ekit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (250)[org.openhab.io.homekit.internal.HomekitCommandExtension(329)] : dm Homekit tracking 1 SingleStatic added {org.openhab.io.homekit.Homekit}={port=9123, qrCode=X-HM://001408XXIFMDB, service.id=517, service.bundleid=250, service.scope=bundle, component.name=org.openhab.io.homekit.internal.HomekitImpl, service.config.label=HomeKit Integration, component.id=330, service.config.factory=false, pin=031-45-158, setupId=FMDB, useOHmDNS=false, service.config.category=io, service.config.description.uri=io:homekit, service.pid=[org.openhab.homekit, org.openhab.homekit]} (exit)

yfre · December 28, 2022, 5:16pm

the log stops at most interesting part. until that point is all standard logging nothing, special.
what do you have in the logs afterwards?

Jacek_Kaczmarczyk · December 29, 2022, 8:03am

i can confirm similar issue on 2 different hosts.
Host 1:
3.4.0 with apple tv acting as a bridge. no answer from local network and remote.
openhab and openhab-ssl visible from mdns query, no _hap entry from homekit addon. Restarting openhab helps. It happen twice in 3 past days.
274 â Active â 80 â 3.4.0 â openHAB Add-ons :: Bundles :: IO :: Homekit

Host2 :
3.4.0 the same situation, speaker as a hub
270 │ Active │ 80 │ 3.4.0.202212202312 │ openHAB Add-ons :: Bundles :: IO :: Homekit
(budle manually updated to 16.2 with home app architecture upgrade)
bundle:restart org.openhab.io.homekit helps

in both cases IOS app is not showing the warning that “bridge is not available” i was used to that in case of normal internet connection drop or sth.

Jacek_Kaczmarczyk · December 29, 2022, 8:57am

dirty workarround but you can put this into crontab to check/refreash the bundle

#!/bin/bash
# homekit serice discoverable
echo "................................................"
date "+%Y.%m.%d %H:%M:%S"
echo " "
avahi-browse -t _hap._tcp |grep openHAB
if [ $? != 0 ]
then

  echo "hap service not found restarting"

  openhab-cli console -p habopen bundle:restart org.openhab.io.homekit

else
   echo "hap service up and running"
fi
echo "................................................"
echo " "
````Preformatted text`

crontab

*/10 * * * * /path/to/script/script.sh >/dev/null 2>&1

yfre · December 29, 2022, 12:35pm

anything in the log files with

log:set TRACE org.openhab.io.homekit.internal

? im looking for something like
"“HomeKit bridge reacting on network interface changes.”
“removed interface”

Jacek_Kaczmarczyk · December 29, 2022, 5:54pm

don’t know because i am running hosts on sdcards, and disabling whole logging during normal operations.
Now i notice homekit down between 10 a.m and 18:45 am. but there is nothing interesting in the logs. No homekit information until i refreshed the bundle at 18:45 but just befour that double checked that there is no _hap service for openhab running

tail -f -n 2000 /var/log/openhab/openhab.log |grep homekit
2022-12-29 18:45:01.679 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension] : BundleComponentActivator : ComponentHolder created.
2022-12-29 18:45:01.685 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : BundleComponentActivator : ComponentHolder created.
2022-12-29 18:45:01.696 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : ConfigurableComponentHolder configuration updated for pid org.openhab.homekit with change count 25
2022-12-29 18:45:01.697 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension] : Dependency Manager created Homekitinterface=org.openhab.io.homekit.Homekit, filter=null, policy=static, cardinality=1..1, bind=setHomekit, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=null
2022-12-29 18:45:01.699 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension] : Component created: DS=DS13, implementation=org.openhab.io.homekit.internal.HomekitCommandExtension, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=null configuration-pid=[org.openhab.io.homekit.internal.HomekitCommandExtension]
2022-12-29 18:45:01.700 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension] : Component Services: scope=singleton, services=[org.openhab.core.io.console.extensions.ConsoleCommandExtension]
2022-12-29 18:45:01.701 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension] : Component Properties: {}
2022-12-29 18:45:01.702 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension] : Querying state disabled
2022-12-29 18:45:01.703 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension] : Querying state disabled
2022-12-29 18:45:01.704 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension] : Component can not be activated since it is in state disabled
2022-12-29 18:45:01.705 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension] : Querying state disabled
2022-12-29 18:45:01.707 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Updating target filters
2022-12-29 18:45:01.708 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : No change in target property for dependency Homekit: currently registered: false
2022-12-29 18:45:01.709 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] :  No existing service listener to unregister for dependency Homekit
2022-12-29 18:45:01.710 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Setting target property for dependency Homekit to null
2022-12-29 18:45:01.711 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : New service tracker for Homekit, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.io.homekit.Homekit), initialReferenceFilter (objectClass=org.openhab.io.homekit.Homekit)
2022-12-29 18:45:01.713 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : dm Homekit tracker reset (closed)
2022-12-29 18:45:01.715 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : dm Homekit tracker opened
2022-12-29 18:45:01.716 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : registering service listener for dependency Homekit
2022-12-29 18:45:01.718 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Changed state from disabled to unsatisfiedReference
2022-12-29 18:45:01.719 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Component enabled
2022-12-29 18:45:01.720 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : ActivateInternal
2022-12-29 18:45:01.721 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Querying state unsatisfiedReference
2022-12-29 18:45:01.722 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Querying state unsatisfiedReference
2022-12-29 18:45:01.723 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Activating component from state unsatisfiedReference
2022-12-29 18:45:01.724 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Querying state unsatisfiedReference
2022-12-29 18:45:01.725 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Querying state unsatisfiedReference
2022-12-29 18:45:01.726 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Dependency not satisfied: Homekit
2022-12-29 18:45:01.727 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Not all dependencies satisfied, cannot activate
2022-12-29 18:45:01.728 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : Dependency Manager created $000interface=org.openhab.core.storage.StorageService, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=0
2022-12-29 18:45:01.729 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : Dependency Manager created $001interface=org.openhab.core.items.ItemRegistry, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=1
2022-12-29 18:45:01.730 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : Dependency Manager created $002interface=org.openhab.core.net.NetworkAddressService, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=2
2022-12-29 18:45:01.731 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : Dependency Manager created $003interface=org.openhab.core.items.MetadataRegistry, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=3
2022-12-29 18:45:01.732 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : Dependency Manager created $004interface=org.osgi.service.cm.ConfigurationAdmin, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=4
2022-12-29 18:45:01.732 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : Dependency Manager created $005interface=org.openhab.core.io.transport.mdns.MDNSClient, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=5
2022-12-29 18:45:01.733 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : Dependency Manager created $006interface=org.openhab.core.service.ReadyService, filter=null, policy=static, cardinality=1..1, bind=null, unbind=null, updated=null, field=null, field-option=null, collection-type=null, parameter=6
2022-12-29 18:45:01.734 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : Component created: DS=DS14, implementation=org.openhab.io.homekit.internal.HomekitImpl, immediate=false, default-enabled=true, factory=null, configuration-policy=optional, activate=activate, deactivate=deactivate, modified=modified configuration-pid=[org.openhab.homekit]
2022-12-29 18:45:01.735 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : Component Services: scope=singleton, services=[org.openhab.io.homekit.Homekit]
2022-12-29 18:45:01.736 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : Component Properties: {service.config.label=HomeKit Integration, port=9123, service.config.category=io, service.config.description.uri=io:homekit, service.config.factory=false, service.pid=org.openhab.homekit}
2022-12-29 18:45:01.737 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : Querying state disabled
2022-12-29 18:45:01.738 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : Querying state disabled
2022-12-29 18:45:01.739 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : Component can not be activated since it is in state disabled
2022-12-29 18:45:01.740 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl] : Querying state disabled
2022-12-29 18:45:01.740 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Updating target filters
2022-12-29 18:45:01.741 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : No change in target property for dependency $000: currently registered: false
2022-12-29 18:45:01.742 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] :  No existing service listener to unregister for dependency $000
2022-12-29 18:45:01.743 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Setting target property for dependency $000 to null
2022-12-29 18:45:01.744 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : New service tracker for $000, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.storage.StorageService), initialReferenceFilter (objectClass=org.openhab.core.storage.StorageService)
2022-12-29 18:45:01.745 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $000 tracker reset (closed)
2022-12-29 18:45:01.749 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.storage.StorageService}={service.id=353, service.bundleid=211, service.scope=bundle, storage.format=json, service.config.label=Json Storage, component.name=org.openhab.core.storage.json, component.id=248, service.config.factory=false, service.config.category=system, service.pid=org.openhab.storage.json, service.config.description.uri=system:json_storage} (enter)
2022-12-29 18:45:01.750 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $000 tracking 1 SingleStatic active: false trackerOpened: false optional: false
2022-12-29 18:45:01.751 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $000 tracking 1 SingleStatic added {org.openhab.core.storage.StorageService}={service.id=353, service.bundleid=211, service.scope=bundle, storage.format=json, service.config.label=Json Storage, component.name=org.openhab.core.storage.json, component.id=248, service.config.factory=false, service.config.category=system, service.pid=org.openhab.storage.json, service.config.description.uri=system:json_storage} (exit)
2022-12-29 18:45:01.752 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $000 tracker opened
2022-12-29 18:45:01.752 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : registering service listener for dependency $000
2022-12-29 18:45:01.753 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : No change in target property for dependency $001: currently registered: false
2022-12-29 18:45:01.754 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] :  No existing service listener to unregister for dependency $001
2022-12-29 18:45:01.755 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Setting target property for dependency $001 to null
2022-12-29 18:45:01.756 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : New service tracker for $001, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.items.ItemRegistry), initialReferenceFilter (objectClass=org.openhab.core.items.ItemRegistry)
2022-12-29 18:45:01.757 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $001 tracker reset (closed)
2022-12-29 18:45:01.759 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $001 tracking 2 SingleStatic added {org.openhab.core.items.ItemRegistry}={service.id=198, service.bundleid=149, service.scope=bundle, component.name=org.openhab.core.internal.items.ItemRegistryImpl, component.id=42} (enter)
2022-12-29 18:45:01.761 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $001 tracking 2 SingleStatic active: false trackerOpened: false optional: false
2022-12-29 18:45:01.762 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $001 tracking 2 SingleStatic added {org.openhab.core.items.ItemRegistry}={service.id=198, service.bundleid=149, service.scope=bundle, component.name=org.openhab.core.internal.items.ItemRegistryImpl, component.id=42} (exit)
2022-12-29 18:45:01.763 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $001 tracker opened
2022-12-29 18:45:01.764 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : registering service listener for dependency $001
2022-12-29 18:45:01.765 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : No change in target property for dependency $002: currently registered: false
2022-12-29 18:45:01.766 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] :  No existing service listener to unregister for dependency $002
2022-12-29 18:45:01.767 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Setting target property for dependency $002 to null
2022-12-29 18:45:01.768 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : New service tracker for $002, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.net.NetworkAddressService), initialReferenceFilter (objectClass=org.openhab.core.net.NetworkAddressService)
2022-12-29 18:45:01.769 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $002 tracker reset (closed)
2022-12-29 18:45:01.771 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $002 tracking 3 SingleStatic added {org.openhab.core.net.NetworkAddressService}={service.id=207, service.bundleid=149, service.scope=bundle, component.name=org.openhab.core.net.NetUtil, service.config.label=Network Settings, component.id=60, useIPv6=false, broadcastAddress=192.168.0.255, service.config.category=system, service.config.description.uri=system:network, service.pid=[org.openhab.network, org.openhab.network], primaryAddress=192.168.0.13/24} (enter)
2022-12-29 18:45:01.772 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $002 tracking 3 SingleStatic active: false trackerOpened: false optional: false
2022-12-29 18:45:01.773 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $002 tracking 3 SingleStatic added {org.openhab.core.net.NetworkAddressService}={service.id=207, service.bundleid=149, service.scope=bundle, component.name=org.openhab.core.net.NetUtil, service.config.label=Network Settings, component.id=60, useIPv6=false, broadcastAddress=192.168.0.255, service.config.category=system, service.config.description.uri=system:network, service.pid=[org.openhab.network, org.openhab.network], primaryAddress=192.168.0.13/24} (exit)
2022-12-29 18:45:01.774 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $002 tracker opened
2022-12-29 18:45:01.775 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : registering service listener for dependency $002
2022-12-29 18:45:01.776 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : No change in target property for dependency $003: currently registered: false
2022-12-29 18:45:01.777 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] :  No existing service listener to unregister for dependency $003
2022-12-29 18:45:01.777 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Setting target property for dependency $003 to null
2022-12-29 18:45:01.778 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : New service tracker for $003, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.items.MetadataRegistry), initialReferenceFilter (objectClass=org.openhab.core.items.MetadataRegistry)
2022-12-29 18:45:01.779 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $003 tracker reset (closed)
2022-12-29 18:45:01.781 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $003 tracking 4 SingleStatic added {org.openhab.core.items.MetadataRegistry}={service.id=197, service.bundleid=149, service.scope=bundle, component.name=org.openhab.core.internal.items.MetadataRegistryImpl, component.id=47} (enter)
2022-12-29 18:45:01.782 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $003 tracking 4 SingleStatic active: false trackerOpened: false optional: false
2022-12-29 18:45:01.783 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $003 tracking 4 SingleStatic added {org.openhab.core.items.MetadataRegistry}={service.id=197, service.bundleid=149, service.scope=bundle, component.name=org.openhab.core.internal.items.MetadataRegistryImpl, component.id=47} (exit)
2022-12-29 18:45:01.784 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $003 tracker opened
2022-12-29 18:45:01.785 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : registering service listener for dependency $003
2022-12-29 18:45:01.786 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : No change in target property for dependency $004: currently registered: false
2022-12-29 18:45:01.787 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] :  No existing service listener to unregister for dependency $004
2022-12-29 18:45:01.788 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Setting target property for dependency $004 to null
2022-12-29 18:45:01.788 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : New service tracker for $004, initial active: false, previous references: {}, classFilter: (objectClass=org.osgi.service.cm.ConfigurationAdmin), initialReferenceFilter (objectClass=org.osgi.service.cm.ConfigurationAdmin)
2022-12-29 18:45:01.789 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $004 tracker reset (closed)
2022-12-29 18:45:01.791 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $004 tracking 5 SingleStatic added {org.osgi.service.cm.ConfigurationAdmin}={osgi.command.scope=cm, service.description=Configuration Admin Service Specification 1.6 Implementation, service.id=40, service.bundleid=12, service.scope=bundle, osgi.command.function=[getConfiguration,getFactoryConfiguration,listConfigurations,createFactoryConfiguration], service.vendor=The Apache Software Foundation, config.plugins=, service.pid=org.apache.felix.cm.ConfigurationAdmin} (enter)
2022-12-29 18:45:01.793 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $004 tracking 5 SingleStatic active: false trackerOpened: false optional: false
2022-12-29 18:45:01.794 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $004 tracking 5 SingleStatic added {org.osgi.service.cm.ConfigurationAdmin}={osgi.command.scope=cm, service.description=Configuration Admin Service Specification 1.6 Implementation, service.id=40, service.bundleid=12, service.scope=bundle, osgi.command.function=[getConfiguration,getFactoryConfiguration,listConfigurations,createFactoryConfiguration], service.vendor=The Apache Software Foundation, config.plugins=, service.pid=org.apache.felix.cm.ConfigurationAdmin} (exit)
2022-12-29 18:45:01.794 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $004 tracker opened
2022-12-29 18:45:01.795 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : registering service listener for dependency $004
2022-12-29 18:45:01.796 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : No change in target property for dependency $005: currently registered: false
2022-12-29 18:45:01.797 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] :  No existing service listener to unregister for dependency $005
2022-12-29 18:45:01.798 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Setting target property for dependency $005 to null
2022-12-29 18:45:01.799 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : New service tracker for $005, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.io.transport.mdns.MDNSClient), initialReferenceFilter (objectClass=org.openhab.core.io.transport.mdns.MDNSClient)
2022-12-29 18:45:01.800 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $005 tracker reset (closed)
2022-12-29 18:45:01.802 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $005 tracking 6 SingleStatic added {org.openhab.core.io.transport.mdns.MDNSClient}={service.id=316, service.bundleid=186, service.scope=bundle, component.name=org.openhab.core.io.transport.mdns.internal.MDNSClientImpl, component.id=204} (enter)
2022-12-29 18:45:01.803 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $005 tracking 6 SingleStatic active: false trackerOpened: false optional: false
2022-12-29 18:45:01.804 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $005 tracking 6 SingleStatic added {org.openhab.core.io.transport.mdns.MDNSClient}={service.id=316, service.bundleid=186, service.scope=bundle, component.name=org.openhab.core.io.transport.mdns.internal.MDNSClientImpl, component.id=204} (exit)
2022-12-29 18:45:01.805 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $005 tracker opened
2022-12-29 18:45:01.806 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : registering service listener for dependency $005
2022-12-29 18:45:01.807 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : No change in target property for dependency $006: currently registered: false
2022-12-29 18:45:01.808 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] :  No existing service listener to unregister for dependency $006
2022-12-29 18:45:01.808 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Setting target property for dependency $006 to null
2022-12-29 18:45:01.809 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : New service tracker for $006, initial active: false, previous references: {}, classFilter: (objectClass=org.openhab.core.service.ReadyService), initialReferenceFilter (objectClass=org.openhab.core.service.ReadyService)
2022-12-29 18:45:01.810 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $006 tracker reset (closed)
2022-12-29 18:45:01.812 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $006 tracking 7 SingleStatic added {org.openhab.core.service.ReadyService}={service.id=196, service.bundleid=149, service.scope=bundle, component.name=org.openhab.core.internal.service.ReadyServiceImpl, component.id=55} (enter)
2022-12-29 18:45:01.813 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $006 tracking 7 SingleStatic active: false trackerOpened: false optional: false
2022-12-29 18:45:01.814 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $006 tracking 7 SingleStatic added {org.openhab.core.service.ReadyService}={service.id=196, service.bundleid=149, service.scope=bundle, component.name=org.openhab.core.internal.service.ReadyServiceImpl, component.id=55} (exit)
2022-12-29 18:45:01.815 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : dm $006 tracker opened
2022-12-29 18:45:01.816 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : registering service listener for dependency $006
2022-12-29 18:45:01.817 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Changed state from disabled to unsatisfiedReference
2022-12-29 18:45:01.818 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Component enabled
2022-12-29 18:45:01.819 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : ActivateInternal
2022-12-29 18:45:01.819 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Querying state unsatisfiedReference
2022-12-29 18:45:01.820 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Querying state unsatisfiedReference
2022-12-29 18:45:01.821 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Activating component from state unsatisfiedReference
2022-12-29 18:45:01.822 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Querying state unsatisfiedReference
2022-12-29 18:45:01.823 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Querying state unsatisfiedReference
2022-12-29 18:45:01.824 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Changed state from unsatisfiedReference to satisfied
2022-12-29 18:45:01.825 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : registration change queue [registered]
2022-12-29 18:45:01.830 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : dm Homekit tracking 1 SingleStatic added {org.openhab.io.homekit.Homekit}={port=9124, startDelay=30, thermostatTargetModeHeat=HeatOn, service.scope=bundle, thermostatTargetModeAuto=Auto, component.name=org.openhab.io.homekit.internal.HomekitImpl, networkInterface=192.168.0.13, useFahrenheitTemperature=false, service.config.category=io, service.pid=[org.openhab.homekit, org.openhab.homekit], qrCode=X-HM://001408WCFW518, service.id=611, service.bundleid=274, thermostatCurrentModeOff=Off, thermostatCurrentModeHeating=Heating, thermostatTargetModeCool=CoolOn, thermostatCurrentModeCooling=Cooling, service.config.label=HomeKit Integration, component.id=366, thermostatTargetModeOff=Off, service.config.factory=false, pin=031-43-103, setupId=W518, useOHmDNS=false, service.config.description.uri=io:homekit} (enter)
2022-12-29 18:45:01.831 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : ActivateInternal
2022-12-29 18:45:01.832 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Querying state unsatisfiedReference
2022-12-29 18:45:01.833 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Querying state unsatisfiedReference
2022-12-29 18:45:01.834 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Activating component from state unsatisfiedReference
2022-12-29 18:45:01.834 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Querying state unsatisfiedReference
2022-12-29 18:45:01.835 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Querying state unsatisfiedReference
2022-12-29 18:45:01.836 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Changed state from unsatisfiedReference to satisfied
2022-12-29 18:45:01.837 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : registration change queue [registered]
2022-12-29 18:45:01.845 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Checking constructor public org.openhab.io.homekit.internal.HomekitCommandExtension()
2022-12-29 18:45:01.847 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Found constructor with 0 arguments : public org.openhab.io.homekit.internal.HomekitCommandExtension()
2022-12-29 18:45:01.848 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : getting bind: setHomekit
2022-12-29 18:45:01.849 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Locating method setHomekit in class org.openhab.io.homekit.internal.HomekitCommandExtension
2022-12-29 18:45:01.850 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : doFindMethod: Looking for method org.openhab.io.homekit.internal.HomekitCommandExtension.setHomekit
2022-12-29 18:45:01.857 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Declared Method org.openhab.io.homekit.internal.HomekitCommandExtension.setHomekit([interface org.osgi.framework.ServiceReference]) not found
2022-12-29 18:45:01.858 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Declared Method org.openhab.io.homekit.internal.HomekitCommandExtension.setHomekit([interface org.osgi.service.component.ComponentServiceObjects]) not found
2022-12-29 18:45:01.859 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : getReferenceClass: Looking for interface class org.openhab.io.homekit.Homekit through loader of org.openhab.io.homekit.internal.HomekitCommandExtension
2022-12-29 18:45:01.860 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : getParameterClass: Found class org.openhab.io.homekit.Homekit
2022-12-29 18:45:01.860 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : doFindMethod: No method taking ServiceReference found, checking method taking org.openhab.io.homekit.Homekit
2022-12-29 18:45:01.861 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : doFindMethod: Found Method public void org.openhab.io.homekit.internal.HomekitCommandExtension.setHomekit(org.openhab.io.homekit.Homekit)
2022-12-29 18:45:01.862 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Found bind method: public void org.openhab.io.homekit.internal.HomekitCommandExtension.setHomekit(org.openhab.io.homekit.Homekit)
2022-12-29 18:45:01.870 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Checking constructor public org.openhab.io.homekit.internal.HomekitImpl(org.openhab.core.storage.StorageService,org.openhab.core.items.ItemRegistry,org.openhab.core.net.NetworkAddressService,org.openhab.core.items.MetadataRegistry,org.osgi.service.cm.ConfigurationAdmin,org.openhab.core.io.transport.mdns.MDNSClient,org.openhab.core.service.ReadyService,java.util.Map) throws java.io.IOException,java.security.InvalidAlgorithmParameterException
2022-12-29 18:45:01.871 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getReferenceClass: Looking for interface class org.openhab.core.storage.StorageService through loader of org.openhab.io.homekit.internal.HomekitImpl
2022-12-29 18:45:01.872 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getParameterClass: Found class org.openhab.core.storage.StorageService
2022-12-29 18:45:01.873 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getReferenceClass: Looking for interface class org.openhab.core.items.ItemRegistry through loader of org.openhab.io.homekit.internal.HomekitImpl
2022-12-29 18:45:01.874 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getParameterClass: Found class org.openhab.core.items.ItemRegistry
2022-12-29 18:45:01.875 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getReferenceClass: Looking for interface class org.openhab.core.net.NetworkAddressService through loader of org.openhab.io.homekit.internal.HomekitImpl
2022-12-29 18:45:01.876 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getParameterClass: Found class org.openhab.core.net.NetworkAddressService
2022-12-29 18:45:01.876 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getReferenceClass: Looking for interface class org.openhab.core.items.MetadataRegistry through loader of org.openhab.io.homekit.internal.HomekitImpl
2022-12-29 18:45:01.877 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getParameterClass: Found class org.openhab.core.items.MetadataRegistry
2022-12-29 18:45:01.878 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getReferenceClass: Looking for interface class org.osgi.service.cm.ConfigurationAdmin through loader of org.openhab.io.homekit.internal.HomekitImpl
2022-12-29 18:45:01.879 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getParameterClass: Found class org.osgi.service.cm.ConfigurationAdmin
2022-12-29 18:45:01.880 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getReferenceClass: Looking for interface class org.openhab.core.io.transport.mdns.MDNSClient through loader of org.openhab.io.homekit.internal.HomekitImpl
2022-12-29 18:45:01.880 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getParameterClass: Found class org.openhab.core.io.transport.mdns.MDNSClient
2022-12-29 18:45:01.881 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getReferenceClass: Looking for interface class org.openhab.core.service.ReadyService through loader of org.openhab.io.homekit.internal.HomekitImpl
2022-12-29 18:45:01.882 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getParameterClass: Found class org.openhab.core.service.ReadyService
2022-12-29 18:45:01.883 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Found constructor with 8 arguments : public org.openhab.io.homekit.internal.HomekitImpl(org.openhab.core.storage.StorageService,org.openhab.core.items.ItemRegistry,org.openhab.core.net.NetworkAddressService,org.openhab.core.items.MetadataRegistry,org.osgi.service.cm.ConfigurationAdmin,org.openhab.core.io.transport.mdns.MDNSClient,org.openhab.core.service.ReadyService,java.util.Map) throws java.io.IOException,java.security.InvalidAlgorithmParameterException
2022-12-29 18:45:01.884 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : This thread collected dependencies
2022-12-29 18:45:01.884 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getService (single component manager) dependencies collected.
2022-12-29 18:45:01.885 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Querying state satisfied
2022-12-29 18:45:01.886 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Querying state satisfied
2022-12-29 18:45:01.887 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : For dependency $000, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.storage.StorageService}={service.id=353, service.bundleid=211, service.scope=bundle, storage.format=json, service.config.label=Json Storage, component.name=org.openhab.core.storage.json, component.id=248, service.config.factory=false, service.config.category=system, service.pid=org.openhab.storage.json, service.config.description.uri=system:json_storage}] service: [null]]]
2022-12-29 18:45:01.888 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : For dependency $001, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.items.ItemRegistry}={service.id=198, service.bundleid=149, service.scope=bundle, component.name=org.openhab.core.internal.items.ItemRegistryImpl, component.id=42}] service: [null]]]
2022-12-29 18:45:01.889 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : For dependency $002, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.net.NetworkAddressService}={service.id=207, service.bundleid=149, service.scope=bundle, component.name=org.openhab.core.net.NetUtil, service.config.label=Network Settings, component.id=60, useIPv6=false, broadcastAddress=192.168.0.255, service.config.category=system, service.config.description.uri=system:network, service.pid=[org.openhab.network, org.openhab.network], primaryAddress=192.168.0.13/24}] service: [null]]]
2022-12-29 18:45:01.890 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : For dependency $003, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.items.MetadataRegistry}={service.id=197, service.bundleid=149, service.scope=bundle, component.name=org.openhab.core.internal.items.MetadataRegistryImpl, component.id=47}] service: [null]]]
2022-12-29 18:45:01.890 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : For dependency $004, optional: false; to bind: [[RefPair: ref: [{org.osgi.service.cm.ConfigurationAdmin}={osgi.command.scope=cm, service.description=Configuration Admin Service Specification 1.6 Implementation, service.id=40, service.bundleid=12, service.scope=bundle, osgi.command.function=[getConfiguration,getFactoryConfiguration,listConfigurations,createFactoryConfiguration], service.vendor=The Apache Software Foundation, config.plugins=, service.pid=org.apache.felix.cm.ConfigurationAdmin}] service: [null]]]
2022-12-29 18:45:01.891 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : For dependency $005, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.io.transport.mdns.MDNSClient}={service.id=316, service.bundleid=186, service.scope=bundle, component.name=org.openhab.core.io.transport.mdns.internal.MDNSClientImpl, component.id=204}] service: [null]]]
2022-12-29 18:45:01.892 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : For dependency $006, optional: false; to bind: [[RefPair: ref: [{org.openhab.core.service.ReadyService}={service.id=196, service.bundleid=149, service.scope=bundle, component.name=org.openhab.core.internal.service.ReadyServiceImpl, component.id=55}] service: [null]]]
2022-12-29 18:45:01.901 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - start HomeKit bridge
2022-12-29 18:45:01.909 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - create HomeKit server with dedicated mDNS server
2022-12-29 18:45:02.438 [TRACE] [.accessories.HomekitAccessoryFactory] - Mandatory characteristics: [Item:RadiatorAC3_homekit_TargetHeatingCoolingMode (Type=StringItem, State=auto, Label=Tryb termostatu Target, Category=null, Tags=[_DYNAMIC_, Room3], Groups=[gRoom3_termostat])  HomeKit type: 'Dummy' characteristic: 'TargetHeatingCoolingMode', Item:RadiatorAC3_TargetTemperature (Type=NumberItem, State=12.0, Label=Temperatura ustawiona, Category=temperature, Tags=[_DYNAMIC_, Room3], Groups=[gRoom3_termostat])  HomeKit type: 'Dummy' characteristic: 'TargetTemperature', Item:TempSensor3_CurrentTemp (Type=NumberItem, State=19.45, Label=Temperatura aktualna, Category=temperature, Tags=[_DYNAMIC_, Room3], Groups=[gRoom3_TempSensor, gRoom3, gRoom3_termostat])  HomeKit type: 'Thermostat' characteristic: 'CurrentTemperature', Item:RadiatorAC3_PWM_Relay (Type=SwitchItem, State=OFF, Label=PWM relay, Category=null, Tags=[_DYNAMIC_, Room3], Groups=[gRoom3_termostat, gRoom3_termostat_PWM])  HomeKit type: 'Dummy' characteristic: 'CurrentHeatingCoolingMode']
2022-12-29 18:45:02.541 [TRACE] [.accessories.HomekitAccessoryFactory] - Mandatory characteristics: [Item:RadiatorAC1_homekit_TargetHeatingCoolingMode (Type=StringItem, State=off, Label=Tryb termostatu Target, Category=null, Tags=[Room1, _DYNAMIC_], Groups=[gRoom1_termostat])  HomeKit type: 'Dummy' characteristic: 'TargetHeatingCoolingMode', Item:RadiatorAC1_TargetTemperature (Type=NumberItem, State=20.0, Label=Temperatura ustawiona, Category=temperature, Tags=[Room1, _DYNAMIC_], Groups=[gRoom1_termostat])  HomeKit type: 'Dummy' characteristic: 'TargetTemperature', Item:TempSensor1_CurrentTemp (Type=NumberItem, State=19.56, Label=Temperatura aktualna, Category=temperature, Tags=[Room1, _DYNAMIC_], Groups=[gRoom1_TempSensor, gRoom1, gRoom1_termostat])  HomeKit type: 'Thermostat' characteristic: 'CurrentTemperature', Item:RadiatorAC1_PWM_Relay (Type=SwitchItem, State=OFF, Label=PWM relay, Category=null, Tags=[Room1, _DYNAMIC_], Groups=[gRoom1_termostat, gRoom1_termostat_PWM])  HomeKit type: 'Dummy' characteristic: 'CurrentHeatingCoolingMode']
2022-12-29 18:45:02.557 [TRACE] [.accessories.HomekitAccessoryFactory] - Mandatory characteristics: [Item:RadiatorAC2_homekit_TargetHeatingCoolingMode (Type=StringItem, State=auto, Label=Tryb termostatu Target, Category=null, Tags=[Room2, _DYNAMIC_], Groups=[gRoom2_termostat])  HomeKit type: 'Dummy' characteristic: 'TargetHeatingCoolingMode', Item:RadiatorAC2_TargetTemperature (Type=NumberItem, State=12.0, Label=Temperatura ustawiona, Category=temperature, Tags=[Room2, _DYNAMIC_], Groups=[gRoom2_termostat])  HomeKit type: 'Dummy' characteristic: 'TargetTemperature', Item:TempSensor2_CurrentTemp (Type=NumberItem, State=19.19, Label=Temperatura aktualna, Category=temperature, Tags=[Room2, _DYNAMIC_], Groups=[gRoom2_TempSensor, gRoom2, gRoom2_termostat])  HomeKit type: 'Thermostat' characteristic: 'CurrentTemperature', Item:RadiatorAC2_PWM_Relay (Type=SwitchItem, State=OFF, Label=PWM relay, Category=null, Tags=[Room2, _DYNAMIC_], Groups=[gRoom2_termostat, gRoom2_termostat_PWM])  HomeKit type: 'Dummy' characteristic: 'CurrentHeatingCoolingMode']
2022-12-29 18:45:02.665 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : getting activate: activate
2022-12-29 18:45:02.666 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Locating method activate in class org.openhab.io.homekit.internal.HomekitImpl
2022-12-29 18:45:02.668 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Declared Method org.openhab.io.homekit.internal.HomekitImpl.activate([interface org.osgi.service.component.ComponentContext]) not found
2022-12-29 18:45:02.669 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Locating method activate in class java.lang.Object
2022-12-29 18:45:02.670 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
2022-12-29 18:45:02.671 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : activate method [activate] not found, ignoring
2022-12-29 18:45:02.672 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Set implementation object for component
2022-12-29 18:45:02.677 [DEBUG] [nhab.io.homekit.internal.HomekitImpl] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitImpl(366)] : Changed state from satisfied to active
2022-12-29 18:45:02.678 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : This thread collected dependencies
2022-12-29 18:45:02.679 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : getService (single component manager) dependencies collected.
2022-12-29 18:45:02.680 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Querying state satisfied
2022-12-29 18:45:02.682 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Querying state satisfied
2022-12-29 18:45:02.683 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : For dependency Homekit, optional: false; to bind: [[RefPair: ref: [{org.openhab.io.homekit.Homekit}={port=9124, startDelay=30, thermostatTargetModeHeat=HeatOn, service.scope=bundle, thermostatTargetModeAuto=Auto, component.name=org.openhab.io.homekit.internal.HomekitImpl, networkInterface=192.168.0.13, useFahrenheitTemperature=false, service.config.category=io, service.pid=[org.openhab.homekit, org.openhab.homekit], qrCode=X-HM://001408WCFW518, service.id=611, service.bundleid=274, thermostatCurrentModeOff=Off, thermostatCurrentModeHeating=Heating, thermostatTargetModeCool=CoolOn, thermostatCurrentModeCooling=Cooling, service.config.label=HomeKit Integration, component.id=366, thermostatTargetModeOff=Off, service.config.factory=false, pin=031-43-103, setupId=W518, useOHmDNS=false, service.config.description.uri=io:homekit}] service: [org.openhab.io.homekit.internal.HomekitImpl@10c0012]]]
2022-12-29 18:45:02.686 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : invoking bind: setHomekit: parameters [org.openhab.io.homekit.internal.HomekitImpl]
2022-12-29 18:45:02.687 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : invoked bind: setHomekit
2022-12-29 18:45:02.689 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : getting activate: activate
2022-12-29 18:45:02.690 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Locating method activate in class org.openhab.io.homekit.internal.HomekitCommandExtension
2022-12-29 18:45:02.691 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Declared Method org.openhab.io.homekit.internal.HomekitCommandExtension.activate([interface org.osgi.service.component.ComponentContext]) not found
2022-12-29 18:45:02.692 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Locating method activate in class org.openhab.core.io.console.extensions.AbstractConsoleCommandExtension
2022-12-29 18:45:02.693 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Declared Method org.openhab.core.io.console.extensions.AbstractConsoleCommandExtension.activate([interface org.osgi.service.component.ComponentContext]) not found
2022-12-29 18:45:02.694 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Locating method activate in class java.lang.Object
2022-12-29 18:45:02.695 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Declared Method java.lang.Object.activate([interface org.osgi.service.component.ComponentContext]) not found
2022-12-29 18:45:02.696 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : activate method [activate] not found, ignoring
2022-12-29 18:45:02.697 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Set implementation object for component
2022-12-29 18:45:02.698 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : Changed state from satisfied to active
2022-12-29 18:45:02.700 [DEBUG] [kit.internal.HomekitCommandExtension] - bundle org.openhab.io.homekit:3.4.0 (274)[org.openhab.io.homekit.internal.HomekitCommandExtension(365)] : dm Homekit tracking 1 SingleStatic added {org.openhab.io.homekit.Homekit}={port=9124, startDelay=30, thermostatTargetModeHeat=HeatOn, service.scope=bundle, thermostatTargetModeAuto=Auto, component.name=org.openhab.io.homekit.internal.HomekitImpl, networkInterface=192.168.0.13, useFahrenheitTemperature=false, service.config.category=io, service.pid=[org.openhab.homekit, org.openhab.homekit], qrCode=X-HM://001408WCFW518, service.id=611, service.bundleid=274, thermostatCurrentModeOff=Off, thermostatCurrentModeHeating=Heating, thermostatTargetModeCool=CoolOn, thermostatCurrentModeCooling=Cooling, service.config.label=HomeKit Integration, component.id=366, thermostatTargetModeOff=Off, service.config.factory=false, pin=031-43-103, setupId=W518, useOHmDNS=false, service.config.description.uri=io:homekit} (exit)
2022-12-29 18:48:10.566 [TRACE] [kit.internal.HomekitAccessoryUpdater] - Received subscription request for RadiatorAC3_homekit_TargetHeatingCoolingMode (Type=StringItem, State=auto, Label=Tryb termostatu Target, Category=null, Tags=[_DYNAMIC_, Room3], Groups=[gRoom3_termostat]) / TargetHeatingCoolingMode
2022-12-29 18:48:10.567 [TRACE] [kit.internal.HomekitAccessoryUpdater] - Adding subscription for RadiatorAC3_homekit_TargetHeatingCoolingMode (Type=StringItem, State=auto, Label=Tryb termostatu Target, Category=null, Tags=[_DYNAMIC_, Room3], Groups=[gRoom3_termostat]) / TargetHeatingCoolingMode
2022-12-29 18:48:10.635 [TRACE] [kit.internal.HomekitAccessoryUpdater] - Received subscription request for RadiatorAC2_homekit_TargetHeatingCoolingMode (Type=StringItem, State=auto, Label=Tryb termostatu Target, Category=null, Tags=[Room2, _DYNAMIC_], Groups=[gRoom2_termostat]) / TargetHeatingCoolingMode
2022-12-29 18:48:10.636 [TRACE] [kit.internal.HomekitAccessoryUpdater] - Adding subscription for RadiatorAC2_homekit_TargetHeatingCoolingMode (Type=StringItem, State=auto, Label=Tryb termostatu Target, Category=null, Tags=[Room2, _DYNAMIC_], Groups=[gRoom2_termostat]) / TargetHeatingCoolingMode
2022-12-29 18:48:10.790 [TRACE] [kit.internal.HomekitAccessoryUpdater] - Received subscription request for RadiatorAC1_homekit_TargetHeatingCoolingMode (Type=StringItem, State=off, Label=Tryb termostatu Target, Category=null, Tags=[Room1, _DYNAMIC_], Groups=[gRoom1_termostat]) / TargetHeatingCoolingMode
2022-12-29 18:48:10.791 [TRACE] [kit.internal.HomekitAccessoryUpdater] - Adding subscription for RadiatorAC1_homekit_TargetHeatingCoolingMode (Type=StringItem, State=off, Label=Tryb termostatu Target, Category=null, Tags=[Room1, _DYNAMIC_], Groups=[gRoom1_termostat]) / TargetHeatingCoolingMode
^[OB^[OA^[[6~^[[6~^[[6~^[[6~^[[6~

yfre · December 29, 2022, 9:01pm

indeed, nothing interesting in the log. just normal start sequence.

i have no idea what this could be, especially as we had not that many changes related to mDNS.
@ccutrer any ideas what could lead to the issue?

the internal logic is simple:

if homekit addon receives a notification from openHAB core that an network interface is down, it removes information from mDNS
on network interface up even, it adds information to mDNS

so, i still think it is related to a short network down&up, maybe on connection lost or some DHCP renew.

ccutrer · December 29, 2022, 9:47pm

My only thought is that with 3.4.0 a bug was introduced with multiple HomeKit bridge instances that it wouldn’t update the correct mDNS info when certain things like all pairings being cleared. But that shouldn’t be an issue for single instance installs. [homekit] Improve multiple instance management by ccutrer · Pull Request #14016 · openhab/openhab-addons · GitHub is the fix for that issue (not yet merged). Beyond that I don’t know. My openHAB box has a static IP, so that could be why I never experience it?

Jacek_Kaczmarczyk · December 30, 2022, 8:06am

i am also pretty sure that it is connected with dynamic ip configuration of openhab host. It’s not the first time for me when i experience this issue (it happened also befor 3.4.0)
i have changed one of my hosts to static IP but still on wlan interface - let you know if the problem exists.
What is interesting - the openhab services

openhab-ssl                                   _openhab-server-ssl._tcp local
openhab                                       _openhab-server._tcp local

are always there, very stable. as far i can remember homebridge is / also stable on one of this hosts - always visible in mdns discovery.

gd35 · December 31, 2022, 9:32am

After 4 days of running, homekit is down again. I was forced to restart the bundle. I enable the trace logging as recommended by @yfre to see what went wrong.

Jacek_Kaczmarczyk · January 2, 2023, 9:15am

i can confirm that the problem is connected to wifi/internet connection issues:
1/ unpowered the router (acting as internet gateway and dhcp server
2/ powered again - network connectivity on host is back openhab service is visible but hap service not. i am using static IP right now (but on wifi connection to router)

Jan  2 10:05:32 raspberrypi dhcpcd[596]: wlan0: IAID 32:53:48:e2
Jan  2 10:05:32 raspberrypi dhcpcd[596]: wlan0: probing address 192.168.0.13/24
Jan  2 10:05:32 raspberrypi dhcpcd[596]: wlan0: soliciting an IPv6 router
Jan  2 10:05:37 raspberrypi dhcpcd[596]: wlan0: using static address 192.168.0.13/24
Jan  2 10:05:37 raspberrypi avahi-daemon[406]: Joining mDNS multicast group on interface wlan0.IPv4 with address 192.168.0.13.
Jan  2 10:05:37 raspberrypi avahi-daemon[406]: New relevant interface wlan0.IPv4 for mDNS.
Jan  2 10:05:37 raspberrypi dhcpcd[596]: wlan0: adding route to 192.168.0.0/24
Jan  2 10:05:37 raspberrypi avahi-daemon[406]: Registering new address record for 192.168.0.13 on wlan0.IPv4.
Jan  2 10:05:37 raspberrypi dhcpcd[596]: wlan0: adding default route via 192.168.0.1

i will run some furher test today - of course after refreshing the bundle hap serivce is back again

2023-01-02 10:03:53.132 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.
2023-01-02 10:05:03.162 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.

after that hap service was not discovered

second test - the same steps, router powered off for a while…

2023-01-02 12:01:03.283 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.
2023-01-02 12:02:08.309 [TRACE] [nhab.io.homekit.internal.HomekitImpl] - HomeKit bridge reacting on network interface changes.

and it’s working - hap service visible without refreshing the bundle