Homekit Service just stops working

Add-ons Bindings
1

Hi,

I have a problem with Homekit Service.
I’ve managed to get Homekit working, but during the day, I have no clue with what kind of circumstances, it just stops working.
I setup a seprate homekit.log on TRACE base, and the last output today was the following (when it stopped working with the iOS APP):

Running OH2 Snapshot Build 806 (but it was the same in all the builds before as well)

4956 2017-02-21 12:59:58.240 [INFO ] [impl.connections.SubscriptionManager] - Publishing changes for 378171486
4957 2017-02-21 12:59:58.240 [INFO ] [impl.connections.SubscriptionManager] - Publishing changes for 378171486
4958 2017-02-21 13:01:09.850 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Received message of length 0. Existing buffer is 0
4959 2017-02-21 13:01:09.851 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Returning 0 results
4960 2017-02-21 13:01:09.852 [INFO ] [.hap.impl.http.impl.AccessoryHandler] - Terminated homekit connection from /192.168.178.31:54351
4961 2017-02-21 13:02:03.600 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Received message of length 0. Existing buffer is 0
4962 2017-02-21 13:02:03.601 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Returning 0 results
4963 2017-02-21 13:02:03.602 [INFO ] [.hap.impl.http.impl.AccessoryHandler] - Terminated homekit connection from /192.168.178.56:49173
4964 2017-02-21 13:02:18.730 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Received message of length 0. Existing buffer is 0
4965 2017-02-21 13:02:18.731 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Returning 0 results
4966 2017-02-21 13:02:18.733 [INFO ] [.hap.impl.http.impl.AccessoryHandler] - Terminated homekit connection from /192.168.178.51:51370
4967 2017-02-21 13:09:59.481 [INFO ] [impl.connections.SubscriptionManager] - Publishing changes for 378171486
4968 2017-02-21 13:09:59.485 [INFO ] [impl.connections.SubscriptionManager] - Publishing changes for 378171486
4969 2017-02-21 13:20:00.883 [INFO ] [impl.connections.SubscriptionManager] - Publishing changes for 482059214
4970 2017-02-21 13:20:00.886 [INFO ] [impl.connections.SubscriptionManager] - Publishing changes for 482059214
4971 2017-02-21 13:20:00.894 [INFO ] [impl.connections.SubscriptionManager] - Publishing changes for 481717091
4972 2017-02-21 13:20:00.899 [INFO ] [impl.connections.SubscriptionManager] - Publishing changes for 481717091
4973 2017-02-21 13:20:00.989 [INFO ] [impl.connections.SubscriptionManager] - Publishing changes for 378171486
4974 2017-02-21 13:20:00.998 [INFO ] [impl.connections.SubscriptionManager] - Publishing changes for 378171486
4975 2017-02-21 13:30:04.458 [INFO ] [impl.connections.SubscriptionManager] - Publishing changes for 378171486
4976 2017-02-21 13:30:04.459 [INFO ] [impl.connections.SubscriptionManager] - Publishing changes for 378171486

These publishing changes message appears every 10mins.

I have 2 iPhones, 2 iPads (wife and myself) and 1 AppleTv which should work with homekit, but I cant make it work consistently. After severval minutes, hours, (even days) it just stops :frowning: All these devices worked fine with Homekit, when I was using elgato poweroutlets. But I wanted to be more flexible when using OH2 devices.

Do I need to setup something special with the AppleTv, that it is recognized at the “main base” for the home-communication?

Usually I could “relive” homekit when doing a bundle:restart xxx from the console. Then the service is communicating with the AppleTV (as expected?) again. And again, some time later, no idea when or why, it stops again.

Any help and/or idea appreciated. I am lost with this one.

Thanks a lot in advance

2

Addon:
After doing a bundle:restart XXX it worked almost 3 hours

The last messages. And it stopped working again :frowning:

24253 00003BC0 33 9D FA 64 B1 8A 0B 59 D6 C3 6B EE 84 3B 0B BF 3..d...Y..k..;..
24254 00003BD0 96 6A D5 26 37 23 AD 1D 67 7E 55 37 90 CC EA E8 .j.&7#..g~U7....
24255 00003BE0 89 0A 09 C0 3B 88 FA B1 B6 EE 64                ....;.....d
24256
24257
24258 2017-02-21 15:47:44.877 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Received message of length 0. Existing buffer is 0
24259 2017-02-21 15:47:44.878 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Returning 0 results
24260 2017-02-21 15:47:44.879 [INFO ] [.hap.impl.http.impl.AccessoryHandler] - Terminated homekit connection from /192.168.178.31:54546
24261 2017-02-21 15:48:37.705 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Received message of length 0. Existing buffer is 0
24262 2017-02-21 15:48:37.706 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Returning 0 results
24263 2017-02-21 15:48:37.707 [INFO ] [.hap.impl.http.impl.AccessoryHandler] - Terminated homekit connection from /192.168.178.56:49362
24264 2017-02-21 16:10:59.909 [INFO ] [impl.connections.SubscriptionManager] - Publishing changes for 378171486
24265 2017-02-21 16:10:59.917 [INFO ] [impl.connections.SubscriptionManager] - Publishing changes for 378171486
24266 2017-02-21 16:10:59.921 [INFO ] [impl.connections.SubscriptionManager] - Publishing changes for 378171486
3

This morning it stopped again but this time there were some error messages in the log:

57872 2017-02-22 10:02:55.695 [ERROR] [lfe.hap.impl.http.impl.BinaryHandler] - Exception in binary handler
57873 java.io.IOException: Die Wartezeit für die Verbindung ist abgelaufen
57874     at sun.nio.ch.FileDispatcherImpl.read0(Native Method)[:1.8.0_121]
57875     at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)[:1.8.0_121]
57876     at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)[:1.8.0_121]
57877     at sun.nio.ch.IOUtil.read(IOUtil.java:192)[:1.8.0_121]
57878     at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)[:1.8.0_121]
57879     at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)[209:org.openhab.io.homekit:2.1.0.201702192000]
57880     at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)[209:org.openhab.io.homekit:2.1.0.201702192000]
57881     at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)[209:org.openhab.io.homekit:2.1.0.201702192000]
57882     at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)[209:org.openhab.io.homekit:2.1.0.201702192000]
57883     at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)[209:org.openhab.io.homekit:2.1.0.201702192000]
57884     at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)[209:org.openhab.io.homekit:2.1.0.201702192000]
57885     at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)[209:org.openhab.io.homekit:2.1.0.201702192000]
57886     at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)[209:org.openhab.io.homekit:2.1.0.201702192000]
57887     at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)[209:org.openhab.io.homekit:2.1.0.201702192000]
57888     at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)[209:org.openhab.io.homekit:2.1.0.201702192000]
57889     at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
57890 2017-02-22 10:02:55.699 [ERROR] [.hap.impl.http.impl.AccessoryHandler] - Exception caught in web handler
57891 java.io.IOException: Die Wartezeit für die Verbindung ist abgelaufen
57892     at sun.nio.ch.FileDispatcherImpl.read0(Native Method)[:1.8.0_121]
57893     at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)[:1.8.0_121]
57894     at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)[:1.8.0_121]
57895     at sun.nio.ch.IOUtil.read(IOUtil.java:192)[:1.8.0_121]
57896     at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)[:1.8.0_121]
57897     at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)[209:org.openhab.io.homekit:2.1.0.201702192000]
57898     at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)[209:org.openhab.io.homekit:2.1.0.201702192000]
57899     at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)[209:org.openhab.io.homekit:2.1.0.201702192000]
57900     at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)[209:org.openhab.io.homekit:2.1.0.201702192000]
57901     at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)[209:org.openhab.io.homekit:2.1.0.201702192000]
57902     at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)[209:org.openhab.io.homekit:2.1.0.201702192000]
57903     at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)[209:org.openhab.io.homekit:2.1.0.201702192000]
57904     at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)[209:org.openhab.io.homekit:2.1.0.201702192000]
57905     at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)[209:org.openhab.io.homekit:2.1.0.201702192000]
57906     at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)[209:org.openhab.io.homekit:2.1.0.201702192000]
57907     at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]

Dont know if these belong to the lost of the connection…

4

no idea, @beowulfe ?

It would be great if you could come up with some suggestions on this one …

5

I’m really not sure. That error doesn’t really point to a cause. You might have to check the iOS logs - HomeKit usually logs quite a bit there.

6

How do I do check the iOS logs?

7

The console logs referred to here: https://developer.apple.com/library/content/qa/qa1747/_index.html

8

Not sure what to look for…there are a lot of homekit messages but I couldnt find one saying “sorry connection broken” (or similar).

Feb 25 17:18:27 Stefans-iPhone-6 locationd[27270] <Notice>: message 'kCLConnectionMessageWatchdog' received from client '/System/Library/PrivateFrameworks/HomeKitDaemon.framework'

or

Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Notice>: Received new connection from Client (unknown) [pid: 28945, connection: 0x121d4c670]
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Client (unknown) [pid: 28945, connection: 0x121d4c670] activated
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Notice>: Putting pid 0 in background 0
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Checking in with incoming message kFetchHomeConfigurationRequestKey (CB0A78BC-08D2-4957-97C4-31BB308A797C) from client 'Home' that does expect a response, payload 
{
    kConfigGenerationCounterKey = 81018,
    kHAPMetadataVersionKey = 604,
}
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Process info is not set in the proxy yet, starting monitoring the connection
Feb 25 17:19:27 Stefans-iPhone-6 Home(HomeKit)[28945] <Info>: Resident provisioning status: 0

or

Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Extracted container app: com.apple.Home, companion app identifier: com.apple.Home, vendor identifier: 0B88FE15-87E7-4406-97D5-E9BCFEACD65D for application identifier com.apple.Home
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Application registry found new Application (B: com.apple.Home, T: (null), C: com.apple.Home) [activeProcesses: 0]
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Application (B: com.apple.Home, T: (null), C: com.apple.Home) [activeProcesses: 1] added Process (28945) AApplication (B: com.apple.Home, T: (null), C: com.apple.Home) [activeProcesses: 1] [state: unknown, connections: 1]
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Sending out notification with foreground app identifiers: {(
)}
Feb 25 17:19:27 Stefans-iPhone-6 identityservicesd[51] <Notice>: Sending messageDictionary: {suppressed} peerMessage <private>  wantsResponse NO timeout (null) fromID: <private> toID (null) toPeople <private> topic com.apple.private.alloy.willow toMyself: YES
Feb 25 17:19:27 Stefans-iPhone-6 identityservicesd[51] <Notice>: Enqueuing message: <private>  to people: <private> service: com.apple.private.alloy.willow (original: <private>)
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Already exists, do not need to proceed further.
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Home manager generation counter 81018/metadata version 604 matches the client(com.apple.Home)
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Notice>: Answering incoming message kFetchHomeConfigurationRequestKey (CB0A78BC-08D2-4957-97C4-31BB308A797C) from client 'Home' that does expect a response
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Sending out notification with foreground app identifiers: {(
    "com.apple.Home"
)}
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Process (28945) AApplication (B: com.apple.Home, T: (null), C: com.apple.Home) [activeProcesses: 1] [state: foreground, connections: 1] is now foreground
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Notice>: Posting notification: kHomeKitAppInForegroundNotification
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Received notification HomeKit App in foreground
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Notice>: Cancelling reachability deregistration deferal timer
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Registering for remote reachability for accessories: (null)
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: [24D26BC2-D34D-45A4-AD7A-F57FEEECCB12] redispatching message kEnableAccessoryReachabilityNotificationRequestKey to resident for home 24D26BC2-D34D-45A4-AD7A-F57FEEECCB12
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Notice>: Activating connections for Process (28945) AApplication (B: com.apple.Home, T: (null), C: com.apple.Home) [activeProcesses: 1] [state: foreground, connections: 1]
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: [Accessory Browser] A HomeKit app is in foreground
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Relaying message: kEnableAccessoryReachabilityNotificationRequestKey to remote peer: [RCH 24D26BC2-D34D-45A4-AD7A-F57FEEECCB12]
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Notice>: Putting pid 28945 in background 0
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Client (Home) [pid: 28945, connection: 0x121d4c670] activated
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Received request to send secure message, <HMDRemoteMessage, Identifier = 914F3B38-7D7E-404C-89CD-F1D6EA85F80F, Name = kEnableAccessoryReachabilityNotificationRequestKey, Destination = <HMDRemoteDeviceMessageDestination, Target = 24D26BC2-D34D-45A4-AD7A-F57FEEECCB12, Device <HMDDevice, Identifier = BDEE41A3-0FA6-5346-B963-9E7C8C26BB77, Name = Wohnzimmer, Version = 3.1.0, Keychain Sync = NO, Cloud Data Sync = YES, Resident Capable = YES, RemoteGateway = YES, Destination = token:ECC7A53FC11E3EA41602903B0563443C3535F405705DB70E4489E4B49A157173/mailto:stefan.danz@icloud.com>>>, to device <HMDDevice, Identifier = BDEE41A3-0FA6-5346-B963-9E7C8C26BB77, Name = Wohnzimmer, Version = 3.1.0, Keychain Sync = NO, Cloud Data Sync = YES, Resident Capable = YES, RemoteGateway = YES, Destination = token:ECC7A53FC11E3EA41602903B0563443C3535F405705DB70E4489E4B49A157173/mailto:stefan.danz@icloud.com>
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: [AWD] MessageTransported -- secure message kEnableAccessoryReachabilityNotificationRequestKey sent over HomeKitMessageTransportType_Secure as HomeKitMessageType_Request
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Securely sending message: <HMDRemoteMessage, Identifier = 914F3B38-7D7E-404C-89CD-F1D6EA85F80F, Name = kEnableAccessoryReachabilityNotificationRequestKey, Destination = <HMDRemoteDeviceMessageDestination, Target = 24D26BC2-D34D-45A4-AD7A-F57FEEECCB12, Device <HMDDevice, Identifier = BDEE41A3-0FA6-5346-B963-9E7C8C26BB77, Name = Wohnzimmer, Version = 3.1.0, Keychain Sync = NO, Cloud Data Sync = YES, Resident Capable = YES, RemoteGateway = YES, Destination = token:ECC7A53FC11E3EA41602903B0563443C3535F405705DB70E4489E4B49A157173/mailto:stefan.danz@icloud.com>>>
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Sending encrypted secure message 
{
    edata = <b07c2ee7 70372b0d 74a477e0 91bcabb1>,
    sid = 5504D144-15FC-4025-9AAA-C6CB6B506843,
    tid = F6891972-0266-4FA0-8B40-8D312A0378FC,
    type = request,
} to <HMDDevice, Identifier = BDEE41A3-0FA6-5346-B963-9E7C8C26BB77, Name = Wohnzimmer, Version = 3.1.0, Keychain Sync = NO, Cloud Data Sync = YES, Resident Capable = YES, RemoteGateway = YES, Destination = token:ECC7A53FC11E3EA41602903B0563443C3535F405705DB70E4489E4B49A157173/mailto:stefan.danz@icloud.com> with options:
{
    kIDSMessageRequestTransactionIDKey = "914F3B38-7D7E-404C-89CD-F1D6EA85F80F";
    kRemoteMessageRestrictionKey = 18446744073709551615;
}
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: Sending message, 0BAFD0C9-C2C8-4D18-94F2-D7C8AEA4B90C, as direct message
Feb 25 17:19:27 Stefans-iPhone-6 homed(HomeKitDaemon)[160] <Info>: [AWD] MessageTransported -- message kSecureClientIDSMessageRequestKey sent over HomeKitMessageTransportType_IDS as HomeKitMessageType_Oneway

Unfortunately I am completely lost :frowning:

9

maybe these errors give more help @beowulfe ?

as the times are very close together I assume they also belong together.
Useless to say, connection has been broken (maybe since the errors

BTW: Build #816 in the meantime.

69112 2017-03-02 08:23:41.118 [ERROR] [lfe.hap.impl.http.impl.BinaryHandler] - Exception in binary handler
69113 java.io.IOException: Die Wartezeit für die Verbindung ist abgelaufen
69114     at sun.nio.ch.FileDispatcherImpl.read0(Native Method)[:1.8.0_121]
69115     at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)[:1.8.0_121]
69116     at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)[:1.8.0_121]
69117     at sun.nio.ch.IOUtil.read(IOUtil.java:192)[:1.8.0_121]
69118     at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)[:1.8.0_121]
69119     at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)[210:org.openhab.io.homekit:2.1.0.201703010723]
69120     at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)[210:org.openhab.io.homekit:2.1.0.201703010723]
69121     at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)[210:org.openhab.io.homekit:2.1.0.201703010723]
69122     at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)[210:org.openhab.io.homekit:2.1.0.201703010723]
69123     at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)[210:org.openhab.io.homekit:2.1.0.201703010723]
69124     at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)[210:org.openhab.io.homekit:2.1.0.201703010723]
69125     at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)[210:org.openhab.io.homekit:2.1.0.201703010723]
69126     at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)[210:org.openhab.io.homekit:2.1.0.201703010723]
69127     at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)[210:org.openhab.io.homekit:2.1.0.201703010723]
69128     at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)[210:org.openhab.io.homekit:2.1.0.201703010723]
69129     at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
69130 2017-03-02 08:23:41.135 [ERROR] [.hap.impl.http.impl.AccessoryHandler] - Exception caught in web handler
69131 java.io.IOException: Die Wartezeit für die Verbindung ist abgelaufen
69132     at sun.nio.ch.FileDispatcherImpl.read0(Native Method)[:1.8.0_121]
69133     at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)[:1.8.0_121]
69134     at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)[:1.8.0_121]
69135     at sun.nio.ch.IOUtil.read(IOUtil.java:192)[:1.8.0_121]
69136     at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)[:1.8.0_121]
69137     at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)[210:org.openhab.io.homekit:2.1.0.201703010723]
69138     at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)[210:org.openhab.io.homekit:2.1.0.201703010723]
69139     at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)[210:org.openhab.io.homekit:2.1.0.201703010723]
69140     at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)[210:org.openhab.io.homekit:2.1.0.201703010723]
69141     at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)[210:org.openhab.io.homekit:2.1.0.201703010723]
69142     at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)[210:org.openhab.io.homekit:2.1.0.201703010723]
69143     at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)[210:org.openhab.io.homekit:2.1.0.201703010723]
69144     at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)[210:org.openhab.io.homekit:2.1.0.201703010723]
69145     at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)[210:org.openhab.io.homekit:2.1.0.201703010723]
69146     at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)[210:org.openhab.io.homekit:2.1.0.201703010723]
69147     at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
69148 2017-03-02 08:23:41.150 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Received message of length 0. Existing buffer is 0
69149 2017-03-02 08:23:41.152 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Returning 0 results
69150 2017-03-02 08:23:41.153 [INFO ] [.hap.impl.http.impl.AccessoryHandler] - Terminated homekit connection from /192.168.178.64:63958
10

In former times, entering bundle:restart XXX in the console restarted the Homekit Bundle and it just appears as connected again in the app.
Nowadays an error shows up in the openhab.log when issuing bundle:restart XXX:

16:28:21.076 [WARN ] [nhab.io.homekit.internal.HomekitImpl] - Could not find existing MAC in org.eclipse.smarthome.storage.json.JsonStorage. Generating new MAC. This will require re-pairing of iOS devices.

So a repairing is needed all the time :frowning: and when using several items for homekit with several rooms/icons a.s.o. you have to define them all the time in the homekit app again :frowning: Fairly frustrating at the moment :expressionless:

br

11

I also have the problem that the HomeKit Service stops. I’m pretty interested in this topic. I moved to openHAB because auf HomeKit and Alexa integration. I would be happy to help finding the problem.
Right now I use 2.1.0-SNAPSHOT in an docker environemnt.

Björn

12

At least from my side, I didnt come any closer to any solution,
I tried so many settings…but the result is allways the same, so I am still waiting for every snapshot to bring up the solution I am looking for, but so far…

br
Stefan

13

I had the same issue where it would work for a while after restarting then suddenly stop. What fixed it for me was disabling IPV6 networking on my OH linux server. Not sure where I read that, but has been working flawlessly for the last for weeks with 30+ tagged devices. For Debian (my server) see https://wiki.debian.org/DebianIPv6#How_to_turn_off_IPv6

14

Hi Dan,

I tried to follow the instructions to disable IPv6 and had success, but I still think IPv6 is still there. When I check it with

lsmod

lsmod

Module                  Size  Used by
....
ipv6                  347620  44

I still see IPv6. Is this the same on you Debian? ( I am using Jessie…)
Unfortunately the success was only some hours (as usual). So I hope you dont see IPv6 with lsmod
and I can continue to search.

Anyway thanks for your suggestion, it gave me hope to solve the problem :smiley:

The log looks a bit different today:

2017-03-23 11:03:18.308 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Received message of length 0. Existing buffer is 0
2017-03-23 11:03:18.310 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Returning 0 results
2017-03-23 11:03:18.311 [INFO ] [.hap.impl.http.impl.AccessoryHandler] - Terminated homekit connection from /192.168.178.31:56084
2017-03-23 11:04:07.193 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Received message of length 0. Existing buffer is 0
2017-03-23 11:04:07.194 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Returning 0 results
2017-03-23 11:04:07.195 [INFO ] [.hap.impl.http.impl.AccessoryHandler] - Terminated homekit connection from /192.168.178.56:56347
2017-03-23 12:27:32.249 [ERROR] [.hap.impl.http.impl.AccessoryHandler] - Exception caught in web handler
java.io.IOException: Die Verbindung wurde vom Kommunikationspartner zurückgesetzt
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method)[:1.8.0_121]
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)[:1.8.0_121]
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)[:1.8.0_121]
        at sun.nio.ch.IOUtil.read(IOUtil.java:192)[:1.8.0_121]
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)[:1.8.0_121]
        at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
2017-03-23 12:27:32.258 [INFO ] [.hap.impl.http.impl.AccessoryHandler] - Terminated homekit connection from /192.168.178.31:56004
2017-03-23 12:58:50.961 [ERROR] [lfe.hap.impl.http.impl.BinaryHandler] - Exception in binary handler
java.io.IOException: Die Wartezeit für die Verbindung ist abgelaufen
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method)[:1.8.0_121]
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)[:1.8.0_121]
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)[:1.8.0_121]
        at sun.nio.ch.IOUtil.read(IOUtil.java:192)[:1.8.0_121]
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)[:1.8.0_121]
        at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
2017-03-23 12:58:50.971 [ERROR] [.hap.impl.http.impl.AccessoryHandler] - Exception caught in web handler
java.io.IOException: Die Wartezeit für die Verbindung ist abgelaufen
        at sun.nio.ch.FileDispatcherImpl.read0(Native Method)[:1.8.0_121]
        at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)[:1.8.0_121]
        at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)[:1.8.0_121]
        at sun.nio.ch.IOUtil.read(IOUtil.java:192)[:1.8.0_121]
        at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)[:1.8.0_121]
        at io.netty.buffer.UnpooledUnsafeDirectByteBuf.setBytes(UnpooledUnsafeDirectByteBuf.java:447)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:880)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:242)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:119)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:511)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:468)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:382)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:354)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:112)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:137)[209:org.openhab.io.homekit:2.1.0.201703212140]
        at java.lang.Thread.run(Thread.java:745)[:1.8.0_121]
2017-03-23 12:58:50.978 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Received message of length 0. Existing buffer is 0
2017-03-23 12:58:50.984 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Returning 0 results
2017-03-23 12:58:50.987 [INFO ] [.hap.impl.http.impl.AccessoryHandler] - Terminated homekit connection from /192.168.178.51:64557
15

I found a easy trick if homekit openhab devices stuck at updating/ no response until restart openhab, I found closed the app (by double tap home than swipe up) than turn off wifi for 2 seconds in iphone/ipad, mostly the case do it 1 time will be ok, the worst case is repeat above step 3 times, so far when I discover this trick, I don’t need restart openhab to bring back homekit in iphone, please share if this trick works or not works.

16

No idea how this should work with so many devices…

As I lost the connection this morning again I tried it, and it did not work at all. If I need to do it with all devices it is far easier to restart the whole raspberry. Anyway I still have no working homekit binding :frowning:

17

what do you mean by so many devices?
no matter how many devices in homekit, there is only one app (Homekit) to control, just close that app (not minimize) than turn off wifi for 2 second, back on wifi, than open homekit app

18

 TV, iPhone 3x, iPad 2x…on all of them is HomeKit

Ok I tried it with one device as describe, unfortunately the same result: “No response” :frowning:

19

too bad this trick doesn’t works on you,
I test it on mine and my wife’s iphone,
mine iphone 7 plus ios 10.1.1
my wife iphone 6 plus ios 10.1.1

since found this trick, I no longer require to restart OH for homekit to command the devices and read the status.

one more info, I make a clean install by 2 weeks ago, as I do many test on OH2 and add/remove devices many times per day, it turns homebridge very slow response and unstable, than I backup only config folders (the parents folder contains items rules things) and make a clean install, after clean install, homebridge work mostly as expected.

20

Sorry for the late response

Yes I still see the module loaded and yes I’m on debian.