search

openhab / openhab-addons

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

[homekit] Excepton encountered while verifying pairing #7750

Closed RafalLukawiecki closed 4 years ago

RafalLukawiecki commented 4 years ago

After bundle:refresh, system reboot, or just OpenHAB service restart, Homekit binding snapshot 2.5.5.202005170417 2.5.5 using the version of OpenHAB officially released with 2.5.4 2.5.5, repeatedly logs the following error and refuses to work. Please note, the error also has a spelling mistake, "Excepton" should say "Exception":

2020-05-23 09:45:37.369 [ERROR] [.server.impl.connections.HttpSession] - Excepton encountered while verifying pairing
java.lang.Exception: Unknown user: F8D7E8B3-9C0F-431A-BF29-9B18DD68AD44
        at io.github.hapjava.server.impl.pairing.PairVerificationManager.stage2(PairVerificationManager.java:113) ~[bundleFile:?]
        at io.github.hapjava.server.impl.pairing.PairVerificationManager.handle(PairVerificationManager.java:51) ~[bundleFile:?]
        at io.github.hapjava.server.impl.connections.HttpSession.handlePairVerify(HttpSession.java:127) [bundleFile:?]
        at io.github.hapjava.server.impl.connections.HttpSession.handleRequest(HttpSession.java:56) [bundleFile:?]
        at io.github.hapjava.server.impl.connections.ConnectionImpl.doHandleRequest(ConnectionImpl.java:56) [bundleFile:?]
        at io.github.hapjava.server.impl.connections.ConnectionImpl.handleRequest(ConnectionImpl.java:49) [bundleFile:?]
        at io.github.hapjava.server.impl.http.impl.AccessoryHandler.channelRead0(AccessoryHandler.java:52) [bundleFile:?]
        at io.github.hapjava.server.impl.http.impl.AccessoryHandler.channelRead0(AccessoryHandler.java:17) [bundleFile:?]
        at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105) [bundleFile:4.1.42.Final]
        at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:374) [bundleFile:4.1.42.Final]
        at io.netty.channel.AbstractChannelHandlerContext.access$600(AbstractChannelHandlerContext.java:56) [bundleFile:4.1.42.Final]
        at io.netty.channel.AbstractChannelHandlerContext$7.run(AbstractChannelHandlerContext.java:365) [bundleFile:4.1.42.Final]
        at io.netty.util.concurrent.DefaultEventExecutor.run(DefaultEventExecutor.java:66) [bundleFile:4.1.42.Final]
        at io.netty.util.concurrent.SingleThreadEventExecutor$6.run(SingleThreadEventExecutor.java:1044) [bundleFile:4.1.42.Final]
        at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74) [bundleFile:4.1.42.Final]
        at io.netty.util.concurrent.FastThreadLocalRunnable.run(FastThreadLocalRunnable.java:30) [bundleFile:4.1.42.Final]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]

Clearing all Homekit pairings in Karaf and re-adding them in the Home app fixes the issue, but it is not, of course, convenient, considering the number of accessories.

Does anyone have any tips how to debug it further?

PS. smarthome:homekit allowUnauthenticated true does not help.

RafalLukawiecki commented 4 years ago

Further clarification: disabling Homekit authentication by using smarthome:homekit allowUnauthenticated true has the effect that the error is no longer logged, but the Home app is no longer able to communicate with any of the accessories and shows "No Response" for each of them.

yfre commented 4 years ago

please check the user id stored in homekit jsondb

cat /var/lib/openhab2/jsondb/homekit.json

you must have an entry user__F8D7E8B3-9C0F-431A-BF29-9B18DD68AD44.

e.g. in my case i have

{ "user_c2:d:4:ce:ac:f7261219C9-2D81-4D63-C616-CBE877D34CB0": { "class": "java.lang.String", "value": "psGthUfHHqk3mwVgyhVem8MZLw2enWo91JGt3QUr21U\u003d" },

if the user is different, then change it but dont touch the "value"

RafalLukawiecki commented 4 years ago

Thank you, @yfre, for your help. My homekit.json does not have a userentry at all. The entire homekit.json contains:

{
  "privateKey": {
    "class": "java.lang.String",
    "value": "Ld***\u003d"
  },
  "salt": {
    "class": "java.lang.String",
    "value": "-15365***031"
  },
  "mac": {
    "class": "java.lang.String",
    "value": "52:***:74"
  },
  "revision": {
    "class": "java.lang.String",
    "value": "15"
  }
}%

I will delete it, including backup, reset pairings and cross my fingers hoping the necessary entry is created on the next start.

yfre commented 4 years ago

probably you have executed at some point "clearPairings" - it deletes the user from the homekit.json.

regarding home app configuration - you can try an OS app called "controller", it can make backup of the home app configuration. if you keep item names unchanged it should be able to restore your configuration (room assignment, icons), etc, after the pairing. however, the free version of controller app keep the backup only for 10 minutes or so.

RafalLukawiecki commented 4 years ago

I am afraid removing homekit.json did not help, but something interesting is happening:

For what it is worth, I have updated the binding to the 2.5.5 released version, but it did not help, either.

yfre commented 4 years ago

"2020-05-23 12:37:24.200 [WARN ] [it.internal.HomekitAccessoryRegistry] - trying to remove org.openhab.io.homekit.internal.accessories.HomekitMotionSensorImpl@3496372d but bridge is null"

is pretty strange. please make sure you have only one instance of homekit binding running/active. no other ideas how that could happened.

ps: the users in homekit.json are the clients, so, you probably have several ios/apple tv devices and they are synced via icloud.

RafalLukawiecki commented 4 years ago

Thank you for continuing to help me, @yfre. Is this a sufficient test to ensure I have only one instance of the homekit binding running/active?:

openhab> feature:list | grep homekit
openhab-misc-homekit                              │ 2.5.5            │ x        │ Started     │ openhab-addons-2.5.5     │ HomeKit Integration
openhab> list -s | grep homekit
244 │ Active │  80 │ 2.5.5                   │ org.openhab.io.homekit

Thank you for explaining about the multiple users. Indeed, I have several iOS devices and a single AppleTV, with iCloud syncing.

Any other ideas what to do next, save for reinstalling everything from scratch?

yfre commented 4 years ago

yes, you have only one instance running.

im running out of ideas. i checked the source code and the only ways to get "users" removed from homekit.json are

and there is no place in the source code which would remove "mac" from the homekit.json

i have only standard advices left: unpair from iOS, uninstall homekit binding, delete homekit.json, restart everything, including iOS devices, reinstall homekit binding, pair again

RafalLukawiecki commented 4 years ago

Ok, I will once again uninstall homekit binding, delete homekit.json, restart everything, including iOS devices, reinstall homekit binding, pair again. This time, I will use the 2.5.6 snapshot, as I see you may have been working on a related issue #7701 / #7702

I wonder if there is any way to log more information to see what is happening prior to the removal of the user from homekit.json. Bear in mind that this issue only arises when OpenHAB shuts down, so my intuition is that OH initiates an action that leads to the loss of those entries in homekit.json.

What is the correct way to install the Homekit binding? I want to make sure I do it the right way when I have cleared the system.

For what it may be worth, I am running OH on FreeBSD. ZWave and RFXCOM are performing well now, following some debugging of nrjavaserial issues in the last few weeks.

RafalLukawiecki commented 4 years ago

I wonder if I am uninstalling/installing the Homekit addon correctly. I removed services/homekit.cfg from the system. I placed the current 2.5.6 snapshot .kar into the addons directory. I have cleared caches, tmp, cleared pairings, deleted from iOS Home app, shut the phone down, restarted OH.

I expected, upon restart, to see no Homekit. However, it started without me "installing" it. According to Karaf, it picked up today's snapshot version:

openhab> feature:list | grep homekit
openhab-misc-homekit                              │ 2.5.5            │          │ Uninstalled │ openhab-addons-2.5.5          │ HomeKit Integration
openhab-misc-homekit                              │ 2.5.6.SNAPSHOT   │ x        │ Started     │ openhab-addons-2.5.6-SNAPSHOT │ HomeKit Integration
openhab> list -s | grep homekit
243 │ Active │  80 │ 2.5.6.202005230619      │ org.openhab.io.homekit

...and it now comes with the new shorter commands like list.

Then, I thought I would change its pin to be sure of a new association in the Home app. Since I no longer had the homekit.cfg, I decided to do that in Paper UI. When I pressed 'Save' I got this in the log:

2020-05-23 14:47:33.613 [ERROR] [org.openhab.io.homekit              ] - bundle org.openhab.io.homekit:2.5.6.202005230619 (243)[org.openhab.io.homekit.internal.HomekitImpl(295)] : The modified method has thrown an exception
java.lang.RuntimeException: HomekitHttpServer can only be started once
        at io.github.hapjava.server.impl.http.impl.HomekitHttpServer.start(HomekitHttpServer.java:34) ~[?:?]
        at io.github.hapjava.server.impl.HomekitRoot.start(HomekitRoot.java:113) ~[?:?]
        at org.openhab.io.homekit.internal.HomekitImpl.startBridge(HomekitImpl.java:150) ~[?:?]
        at org.openhab.io.homekit.internal.HomekitImpl.modified(HomekitImpl.java:108) ~[?:?]
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:1.8.0_252]
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[?:1.8.0_252]
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:1.8.0_252]
        at java.lang.reflect.Method.invoke(Method.java:498) ~[?:1.8.0_252]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod.invokeMethod(BaseMethod.java:228) ~[bundleFile:?]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod.access$500(BaseMethod.java:41) ~[bundleFile:?]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod$Resolved.invoke(BaseMethod.java:664) ~[bundleFile:?]
        at org.apache.felix.scr.impl.inject.methods.BaseMethod.invoke(BaseMethod.java:510) [bundleFile:?]
        at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:317) [bundleFile:?]
        at org.apache.felix.scr.impl.inject.methods.ActivateMethod.invoke(ActivateMethod.java:307) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.invokeModifiedMethod(SingleComponentManager.java:836) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.modify(SingleComponentManager.java:791) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.reconfigure(SingleComponentManager.java:709) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.SingleComponentManager.reconfigure(SingleComponentManager.java:673) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.ConfigurableComponentHolder.configurationUpdated(ConfigurableComponentHolder.java:435) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.RegionConfigurationSupport.configurationEvent(RegionConfigurationSupport.java:316) [bundleFile:?]
        at org.apache.felix.scr.impl.manager.RegionConfigurationSupport$2.configurationEvent(RegionConfigurationSupport.java:118) [bundleFile:?]
        at org.apache.felix.cm.impl.ConfigurationManager$FireConfigurationEvent.sendEvent(ConfigurationManager.java:1709) [bundleFile:?]
        at org.apache.felix.cm.impl.ConfigurationManager$FireConfigurationEvent.run(ConfigurationManager.java:1651) [bundleFile:?]
        at org.apache.felix.cm.impl.UpdateThread.run0(UpdateThread.java:138) [bundleFile:?]
        at org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:105) [bundleFile:?]
        at java.lang.Thread.run(Thread.java:748) [?:1.8.0_252]

Could it be related to your hunch about multiple instances somehow running?

What is the correct way to uninstall and install this binding? Many thanks, @yfre, for your help. Homekit is the last barrier stopping me from migrating from OH1 (where I had Homekit running well over Homebridge, which is now off).

RafalLukawiecki commented 4 years ago

First of all, I think changing the pin to a new one, then doing the reset, may have had a positive effect. 🤞 I cannot be sure yet, but the config has survived a couple of restarts. I am now using 2.5.6 today's snapshot.

Secondly, I have noticed something odd about the revision property that is stored in homekit.json. After the reinstall and cleaning, homekit.json had no users yet but it had a new mac. It showed revision=2. However, after doing the pairings, revision reverted back to 1:

  "revision": {
    "class": "java.lang.String",
    "value": "1"
  },

I wonder if this is the expected behaviour and if that could be related to some of the issues that I was experiencing. For example, is it possible that as we were cleaning/reinstalling, Homekit was being told that the revision number was lower than the one it expected? If so, then it would be good to make sure this number always goes up or to document that otherwise the pin needs to be changed when removing homekit.json.

Lastly, I am still lost as to why the homekit add on keeps installing itself. Even if I feature:uninstall openhab-misc-homekit it will reinstall itself less than a minute later. I do not know what it is in the config that makes it so persistent—do you?

I will report later if and how the set-up kept on behaving, hopefully I will not lose it after the next reboots. Oh, I have downloaded the Controller for Homekit app. I need to pay €10 to get the backup functionality. If you feel it is worth it, I will—however, does it permit a partial restore, say of only the openHAB-related settings? Thanks, @yfre.

yfre commented 4 years ago

@RafalLukawiecki happy to hear that it works for you. not sure what it keeps installing itself. maybe you have it in addons folder or in service/addons.cfg

regarding controller app - in the free version you can do backup for 10 minutes. you dont need to pay for it. so, if you do major change in openHAB then it could be a good idea to make this backup. even for 10 minutes.

regarding revision: strange. we have only the logic to increase the revision and not to decrease. the only case we set revision to "1" if we cannot read it from homekit.json, e.g. homekit.json does not exists, empty or is not accessible.

i will try to re-produce your setup - i.e. have mac and revision but no users.

but in general, we send revision number to the clients on pairing and from that point, clients expects revision to get increased on changes and never get decreased. the revision number change indicates to clients that they need to request the complete configuration from the server, including meta information like device names, max/min values, etc.

yfre commented 4 years ago

@RafalLukawiecki i could not re-produce the issue with "revision" number reset. i removed the users, left everything else untouched, paired again and revision was correct.

have you experienced this issue again ? do we need this issue open or close it?

RafalLukawiecki commented 4 years ago

Thanks for checking with me, @yfre. I have not experienced this issue since changing the HomeKit PIN. The revision number has been incrementing correctly, and I have not experienced HomeKit resets.

I wonder if I had a combination of issues that were acting together to cause this effect. In particular, I wonder if HomeKit itself was asking to remove the pairings when it saw the revision number reset with the same PIN—but I still do not understand why the revision number was resetting...

yfre commented 4 years ago

it looks like everything is working now as expected. closing the ticket.

bigblue1735 commented 4 years ago

Hi, i can confirm. Update the key in config file and cleanup the data and cache will fix this issue.

yfre commented 4 years ago

reopen as more users have reported this issue, see https://community.openhab.org/t/re-solved-homekit-integration-pairing-problems-ios-10-11/101667/4

@bigblue1735 @RafalLukawiecki have you experienced this issue again or is everything working fine and stable now?

RafalLukawiecki commented 4 years ago

So far, everything has worked well for me, and the issue did not come back. I have a feeling the issue may be related to using the same Homekit pin and doing a reset of the pairing + cache clearing. When I switched to the mode of changing the PIN when doing the resets, things were OK.

Having said that, I had not needed to do a reset of any kind for a month or so, and just casually adding or removing/changing Homekit-exposed items causes no issues. I have 58 items exposed and they are all behaving very nicely.