To prove that the destruction of homekit.json at OH shutdown is the issue, I temporarily made it read-only to OH (when OH was running). I still see the messages at shutdown …
[WARN ] [it.internal.HomekitAccessoryRegistry] - trying to remove org.openhab.io.homekit.internal.accessories.HomekitSwitchImpl@831cdb but bridge is null
But on restart I do not get the message about the missing mac AND the paring stays intact and homekit works.
I realise that this is not a solution - but it may help discover the under lying issue.
There is a thread somewhere which suggests to clear pairings and restart twice. I can’t remember the exact steps off the top of my head. I was having a problem with the MAC address being forgotten and it helped me.
Gavin, thank you for the detailed analysis! We had reports about this issue in the past but could never find out the reason and fix it. maybe we will do it with your help.
i checked the source code and there is no place with “remove mac”. it has actually only 2 lines dealing with mac in the complete binding source code
get mac from homekit.json
generate new mac and store it
there is nothing like “remove mac” or “clear mac”.
second observation from code.
“trying to remove … but bridge is null” happens only if openhab informs homekit about changes in the items configuration. it should not get execute on binding stop or start. only on items config change.
could you please do one more test:
start openhab with homekit binding
check revision number in homekit.json
changes something in items config (e.g. remove one line or add one line)
wait for 20 seconds or so
check revision number in homekit.json. it should get increased
shutdown openhab and check revision number one more time
I gave OH back RW access to the homekit.json file
With OH running the revision was “5”.
I changed an item and saw in the log that the item file was refreshed. The revision remained at “5”.
I then tried to shutdown OH - it crashed (and I’m guessing did not run the shutdown routines)
With OH down, I checked homekit.json and it was the same - revision “5”
I started OH and did not get the “Could not find existing MAC in” message in the log - it started ok and Homekit works.
I changed an items file again and again checked homekit.json - revision is still “5”
I then stopped the OH service and got 39 messages …
2020-06-18 21:34:23.746 [WARN ] [it.internal.HomekitAccessoryRegistry] - trying to remove org.openhab.io.homekit.internal.accessories.HomekitSwitchImpl@19d41de but bridge is null
With OH stopped the revision is now “6” but now the mac entry is still there - this is strange as in previous testing, after stopping OH the homekit.json file only contained a revision entry.
I am now going to clearPairings/remove the binding/clear cache and try to reproduce this behaviour.
So, next tests to try and reproduce the same behaviour.
I should say that OH has been stable and has had zero issues for quite a few months before this issue.
I removed the homekit binding, deleted homekit.json and all backups. Cleared the OH cache then restarted the OH service twice. The second time OH started with a clean log - no errors and no warnings.
I then installed the homekit binding and got the warning “Could not find existing MAC” - I guess this is expected.
At this point the homekit.json file has a mac entry, but no revision.
I changed an item, waited 20 seconds and checked homekit.json - now the file ONLY has a revision entry “2” - the mac and other entries are gone.
I restart the service and get the log entry “Could not find existing MAC”. The json file now has all expected entries and revision “3”. Lots of exception warnings in the log during restart (unlike the clean start when homekit was not installed).
The other odd thing is that i get a log entry …
2020-06-18 22:08:39.896 [INFO ] [mekit.internal.HomekitChangeListener] - Created 38 HomeKit items.
When I search for “homekit=” across all items files it get a total of 62 - this is the expected number of homekit enabled items. I think (but am not sure) that all items that are missing are homekit=“Lighting”. The ones that are there are homekit=“Switchable” and temperature.
Please just let me know if I can provide any other info.
I really appreciate your help - this one has me stuck.
@rrgeorge you did an investigation on this issue last time (3 years ago)
do you remember what was the root cause for this issue?
looking on homekit binding code i cannot find anything that would result in deleting mac address from homekit.json and anything i can do to ensure that mac address is stored. i cannot flush storage, i can only do "storage.put(“mac”, …).
I think the problem was that the new MAC wasn’t being stored till you shutdown the binding, and if you paired with iOS, then it didn’t get stored for some reason.
If by “stored” you mean written to homekit.json, then I am not sure that this is correct.
After OH starts I can see the MAC entry in the JSON file. After OH stops it is gone. It is being removed when OH shuts down (I think at the same time as it generates the log entry …
[WARN ] [it.internal.HomekitAccessoryRegistry] - trying to remove org.openhab.io.homekit.internal.accessories.HomekitSwitchImpl@12b6389 but bridge is null
BTW - I have removed all items files except 1 to confirm that it is not being caused by an error in an items file … it is not. After doing this and putting all items files back, I get these two log entries …
2020-06-19 10:53:30.567 [INFO ] [mekit.internal.HomekitChangeListener] - Created 0 HomeKit items.
2020-06-19 10:53:30.578 [WARN ] [homekit.internal.HomekitAuthInfoImpl] - Could not find existing MAC in org.eclipse.smarthome.storage.json.internal.JsonStorage. Generating new MAC. This will require re-pairing of iOS devices.
So not I have zero homekit items (no changes to items files, just removed and readded them).
openhab> smarthome:homekit listAccessories
523133216 Air Conditioner High
2135578493 Bedroom Fan Power
63456321 Air Conditioner
325175901 Drinks Fridge
345729927 Fence Unit
1617624282 Laser Printer
1415582307 Gavins Workstation
2011523614 Garage Display
1707441023 Tablet Weather
995698941 Dexters Door
147694675 AirCon Master
595972165 Away Mode
1666435640 Coolroom
1236620193 Dishwasher
72359997 Pond Pump
1967127131 Air Conditioning
1228445719 Bathroom Fan
1967127130 Air Con
1683166461 Outside Lights
995698940 Hobsons Door
358611059 Air Conditioner Medium
640342911 Air Conditioner Low
1324680971 Tablet Screen
2005209109 Livingroom Fan Power
946044987 Garage Door
1486063088 TV
2011288448 Catbed
1347040216 ALL Lights
1796641134 Can Crusher
985637253 Office Fan
1180901637 Plant Mist
744321183 Garage Lights
1248978364 Guest Room Fan
472362949 Aux Charger
473520579 Green Room LED Color
1876784414 Bug Zapper
675285741 Tracys Workstation
168669480 Greenroom Lights
2143150586 Alarm System
143441191 Generator
openhab>
Here are two items - the light is not working, the fan is working
//=========================================================================================================================
// Office Light
Switch Office_Light "Office Light [%s]" <light> (gOffice, gLights, gSleep, gAway,gPowerSave)
{ channel="mqtt:topic:pi1_mqtt:Office_Light:Office_Light" , alexa="Lighting", homekit="Lighting"}
Number Office_Light_RSSI "Office Light RSSI [%d%%]" <network>
{ channel="mqtt:topic:pi1_mqtt:Office_Light:Office_Light_RSSI" }
Number Office_Light_STA "Office Light State Age [JS(t_mins.js):%s]" <time>
{ channel="mqtt:topic:pi1_mqtt:Office_Light:Office_Light_STA" }
String Office_Light_CMD "Office_Light_CMD[%s]"
{ channel="mqtt:topic:pi1_mqtt:Office_Light:Office_Light_CMD" }
String Office_Light_STATE "Office Light MQTT State [%s]" <switch> (gMapDBpersist,gDeviceOffline,gMQTT_Monitor)
{ channel="mqtt:topic:pi1_mqtt:Office_Light:Office_Light_STATE" }
//=========================================================================================================================
// Office Fan
Switch Office_Fan "Office Fan [%s]" <fan_ceiling> (gOffice, gSleep, gAway,gPowerSave)
{ channel="mqtt:topic:pi1_mqtt:Office_Fan:Office_Fan" , alexa="Switchable" , homekit="Switchable"}
Number Office_Fan_RSSI "Office_Fan RSSI [%d%%]" <network>
{ channel="mqtt:topic:pi1_mqtt:Office_Fan:Office_Fan_RSSI" }
Number Office_Fan_STA "Office_Fan State Age [JS(t_mins.js):%s]" <time>
{ channel="mqtt:topic:pi1_mqtt:Office_Fan:Office_Fan_STA" }
String Office_Fan_CMD "Office_Fan_CMD[%s]"
{ channel="mqtt:topic:pi1_mqtt:Office_Fan:Office_Fan_CMD" }
String Office_Fan_STATE "Office Fan MQTT State [%s]" <switch> (gMapDBpersist,gDeviceOffline,gMQTT_Monitor)
{ channel="mqtt:topic:pi1_mqtt:Office_Fan:Office_Fan_STATE" }
Interestingly, no items tagged as Lighting are working - however, if I change the lighting tag to switchable - it still doesn’t work!
If I change an item that is tagged as switchable to lighting - it still works!
Edit - no items tagged as lighting are working EXCEPT group items tagged as lighting (as in all_lights).
thanks. this is the use case we have not tested with new redesigned homekit biding yet - a group with homekit=“Lighting” which has items with homekit=“Lighting” inside.
we test and report here.
i could reproduce your issue with missing homekit items. basically if lighting is attached to the group and ignore the items inside of the group. im working on a fix, will take few days. i will post here once the fix is available.
