[homekit] "No response" error on all openHAB items

what do you mean with publish?

When I run the Docker container I use below option:

-p 9124:9124

Btw - HomeKit is stable now since several hours :slight_smile:
Lets fingers crossed

Update: After almost 6hours the HomeKit connection failed again :cry:
I hope @yfre can support to solve the problem soon.

@stefan13 @muelli1967

i have just committed the change, which makes the new logic for mDNS configurable and disable by default, i.e. it works by default as it was in OH3.0 release. please check once it get merged.

could you please check one thing for me with the current, not working version. next time the homekit connection fails, could you please check with discovery app (for iOS or mac) whether you see openHAB there.

looks like this (i have 2 openhab running)

1 Like

Thanks, Eugen. I will have a look once it is merged and in the meantime take a screenshot when the connection fails. so far no disconnect since yesterday

thanks a lot eugen.
I had to refresh the bundle this morning again - currently it is working, but I suppose it will terminate the connection in the next few hours again.

I will provide you the discovery output once it fails the next time.

Hi just recognized a strange think - I suppose this is not correct, but maybe I’m wrong.

The configured HomeKit Port is 9124

However, in the DiscoveryApp I see port 9123 :thinking:

Does this make sense for you? Is this an expected behavior because of the recent update you did?

I’m wondering this can work, as I do not expose the port 9123 outside the Docker container.

    docker run -it \
        --name $OH_NAME \
        --net=host \
        -v $DIR_ADDONS:/openhab/addons \
        -v $DIR_CONF:/openhab/conf \
        -v $DIR_USERDATA:/openhab/userdata \
        -e "EXTRA_JAVA_OPTS=-Duser.timezone=Europe/Berlin -Duser.country=DE -Duser.language=de" \
        -d \
        --restart=always \
        --privileged \
        -e USER_ID=99 \
        -e GROUP_ID=999 \
        -e OPENHAB_HTTP_PORT=8192 \
        -e OPENHAB_HTTPS_PORT=8193 \
        -p 9124:9124  \
        -p 9125:9125  \
        -p 9126:9126  \
        -p 9128:9128  \
        -p 9129:9129  \
        -p 43439:43439  \
        -p 8192:8192  \
        -p 8193:8193  \
        -p 1883:1883  \
        openhab/openhab:$OH_VERSION

Not sure if it helps, though with connection broken and if I try to add new device in Home app not using QR code but scanning the network I do see openhab bridge (attached).

This, however, as well sometimes does not happen (discovery), I remember clearly I tried to add new device the same way few days ago, and nothing has appeared.

Thanks!

image|281x499

that what i have discovered today as well. the settings shows 9124 and also documentation says 9124 but the actual port used by homekit biding is 9123. at the end, it can be any port. home app uses mDNS discovery to find the port, but documentation & settings must be aligned. so, i fix it with the PR as well.

Homekit just terminated again :frowning:

I can see now 3 entries for both _openhab-server-ssl and _openhab.server - this morning I had 2 entries only for each.

it looks like docker creates suddenly one additional ipv6 address, openhab make us of this additional address, means it can be reached under this new address. but homekit can use only one address and get confused by the new address.

i would recommend:

  • set ipv4 address in the homekit settings
  • deactive ipv6 support either on docker level or via this java parameter
    -Djava.net.preferIPv4Stack=true

I always had the same issue, not only since 3.1.0.M2. The issue still occurs on 3.1.0.M2 Milestone Build
Even the nightly reboot cron job does not help since HomeKit crashes during the day again. Restarting the bundle (bundle:refresh org.openhab.io.homekit) helps for me.

In crashed state, Discovery app shows _hap._tcp. with only one entry for Philips Hue. In normal mode, it shows openHab as well. The Openhab server entry is always showing okay in discovery app and running without issues.

I have now tried setting -Djava.net.preferIPv4Stack=true. Will report in a few days.

Karaf version               4.2.7
  Karaf home                  /usr/share/openhab/runtime
  Karaf base                  /var/lib/openhab
  OSGi Framework              org.eclipse.osgi-3.12.100.v20180210-1608

JVM
  Java Virtual Machine        OpenJDK Client VM version 11.0.10+9-LTS
  Version                     11.0.10
  Vendor                      Azul Systems, Inc.
  Pid                         718
  Uptime                      14 hours 50 minutes
  Process CPU time            32 minutes
  Process CPU load            0.00
  System CPU load             0.75
  Open file descriptors       312
  Max file descriptors        102,642
  Total compile time          23.231 seconds
Threads
  Live threads                195
  Daemon threads              107
  Peak                        222
  Total started               18955
Memory
  Current heap size           62,651 kbytes
  Maximum heap size           316,800 kbytes
  Committed heap size         190,400 kbytes
  Pending objects             0
  Garbage collector           Name = 'Copy', Collections = 623, Time = 15.173 seconds
  Garbage collector           Name = 'MarkSweepCompact', Collections = 4, Time = 2.089 seconds
Classes
  Current classes loaded      18,742
  Total classes loaded        18,806
  Total classes unloaded      64
Operating system
  Name                        Linux version 5.10.11-v7+
  Architecture                arm
  Processors                  4

Here are the logs that I catched during that time:

2021-03-06 16:09:09.235 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Received message of length 196. Existing buffer is 0
2021-03-06 16:09:09.237 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 196
2021-03-06 16:09:09.238 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Read complete message
2021-03-06 16:09:09.240 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Returning 1 results
2021-03-06 16:09:09.242 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Received data [/192.168.178.20:49175]:
PUT /characteristics HTTP/1.1
Host: openHAB._hap._tcp.local
Content-Length: 58
Content-Type: application/hap+json

{"characteristics":[{"aid":1072355289,"iid":9,"value":0}]}
2021-03-06 16:09:09.245 [TRACE] [er.impl.http.HomekitClientConnection] - 204 /characteristics
2021-03-06 16:09:09.249 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Sending data [/192.168.178.20:49175]:
HTTP/1.1 204 No Content
Content-type: application/hap+json
Connection: keep-alive


2021-03-06 16:09:09.250 [TRACE] [server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 105, cap: 256) [/192.168.178.20:49175]:
57004D18FA93272397347234409F10D7CB3A4A708988DCD74FF7FDE1830DA7982639D900D3FAAC60867ACABCFED53D683B07A7E33EB39E6FD28F48B7932049D6A55447022FABFFAC26BFB5088003E52E68C158DF82BC99F39CA1253DBD3CF7DF0F7BBFD8AC8AFE58E4

2021-03-06 16:09:09.253 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1072355289
2021-03-06 16:09:45.756 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 16:13:12.685 [TRACE] [server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 98, cap: 448) [/192.168.178.20:49175]:
50006213B8ED84B0B7824F6C72C25517251D3DB601FF9930C196A0F9F72D90A749A2170FD9AF994CA4D9A064EA112C54012E601C291CCDAF36D8871F675F479C62BB637E8306859353658CAC0A0E545BC0DF40161E8688A3D470EA0BB72334F2CF00

2021-03-06 16:13:12.689 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Received message of length 98. Existing buffer is 0
2021-03-06 16:13:12.690 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 98
2021-03-06 16:13:12.691 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Read complete message
2021-03-06 16:13:12.693 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Returning 1 results
2021-03-06 16:13:12.694 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Received data [/192.168.178.20:49175]:
GET /characteristics?id=1072355289.9 HTTP/1.1
Host: openHAB._hap._tcp.local


2021-03-06 16:13:12.700 [TRACE] [er.impl.http.HomekitClientConnection] - 200 /characteristics?id=1072355289.9
2021-03-06 16:13:12.708 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Sending data [/192.168.178.20:49175]:
HTTP/1.1 200 OK
Content-type: application/hap+json
Content-Length: 62
Connection: keep-alive

{"characteristics":[{"value":false,"aid":1072355289,"iid":9}]}
2021-03-06 16:13:12.712 [TRACE] [server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 179, cap: 256) [/192.168.178.20:49175]:
A10055BB574AB2CC67DA427EBD2E1EEED6FE24EC17246E574B8E8F910451ACF37391E8DA8F80B3F49A4D1C1F1F218713B68FB6D7689C4C1A66C29438BBC6990B75A64495A2A9E7190B0DC61EED6BC16501EC342E31631571B777F4111DD487E5E68739F75FFDDD9A9E800EDB3081DB1AFDDBB29CFDC8BA266441F069E996688E839630493E33C3D220768A0AA3271B7301410C43A38866C114E70FB3BCA2A968512AFD7BD72E4052540A54B6E02D6

2021-03-06 16:13:12.755 [TRACE] [server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 196, cap: 448) [/192.168.178.20:49175]:
B200527E9CA7F0852C6F87A19777D06EA7B2C6705501C46531C42A40DC395CE62D3A87691BC747EBB3AAEB9EE6D4B0C21318441FC9B4D874612637908453D6AEBF44139ACAE4339CBFF73C9D716A65F632828F781FDB7EA9AEAD8B16B8D8291885443941CC9B28B73B01C25297B120089FAA92063EC6F080764C18745AAA920E1EE42F9EB7015A0CC49192A7C6AD5673A99CD2E3B6F472BB47B4790042B4B17219B73E81B352492FA12F7AD2254F4061930E748E1F2CD7814808A986EDA6D25777334F0F

2021-03-06 16:13:12.756 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Received message of length 196. Existing buffer is 0
2021-03-06 16:13:12.757 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 196
2021-03-06 16:13:12.758 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Read complete message
2021-03-06 16:13:12.759 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Returning 1 results
2021-03-06 16:13:12.761 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Received data [/192.168.178.20:49175]:
PUT /characteristics HTTP/1.1
Host: openHAB._hap._tcp.local
Content-Length: 58
Content-Type: application/hap+json

{"characteristics":[{"aid":1072355289,"iid":9,"value":1}]}
2021-03-06 16:13:12.764 [TRACE] [er.impl.http.HomekitClientConnection] - 204 /characteristics
2021-03-06 16:13:12.767 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Sending data [/192.168.178.20:49175]:
HTTP/1.1 204 No Content
Content-type: application/hap+json
Connection: keep-alive


2021-03-06 16:13:12.770 [TRACE] [server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 105, cap: 256) [/192.168.178.20:49175]:
5700ADA45FFCC8646990E547C0605DF0110C04FF6C78874CCAE63F447357965D91A1BE053B8567CE5237CAAF4C71B2F87648EBDAF3033886AFA21A063B2D2E30D51D495EEA25E883C74D3E9C750A038C8E638389A5CE9BBBB7B45DD9C5D316B2CBA13B7CD5EE2

2021-03-06 16:13:12.775 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1072355289
2021-03-06 16:17:01.906 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 831172396
2021-03-06 16:17:36.195 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 216672649
2021-03-06 16:17:38.579 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Exception in binary handler
java.io.IOException: Connection timed out
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
	at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:247) ~[bundleFile:4.1.42.Final]
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1147) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:635) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:552) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514) [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:834) [?:?]
2021-03-06 16:17:38.585 [DEBUG] [rver.impl.http.impl.AccessoryHandler] - Exception caught in web handler
java.io.IOException: Connection timed out
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
	at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:247) ~[bundleFile:4.1.42.Final]
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1147) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:635) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:552) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514) ~[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:834) [?:?]
2021-03-06 16:17:38.591 [TRACE] [rver.impl.http.impl.AccessoryHandler] - Terminated HomeKit connection from /192.168.178.11:51015
2021-03-06 16:18:47.037 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 16:19:55.606 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 129206442
2021-03-06 16:20:08.468 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1466450999
2021-03-06 16:22:56.977 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1466450999
2021-03-06 16:23:26.596 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 216672649
2021-03-06 16:28:14.726 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 16:28:33.940 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Exception in binary handler
java.io.IOException: Connection timed out
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
	at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:247) ~[bundleFile:4.1.42.Final]
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1147) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:635) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:552) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514) [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:834) [?:?]
2021-03-06 16:28:33.947 [DEBUG] [rver.impl.http.impl.AccessoryHandler] - Exception caught in web handler
java.io.IOException: Connection timed out
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
	at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:247) ~[bundleFile:4.1.42.Final]
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1147) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:635) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:552) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514) ~[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:834) [?:?]
2021-03-06 16:28:33.955 [TRACE] [rver.impl.http.impl.AccessoryHandler] - Terminated HomeKit connection from /192.168.178.4:60059
2021-03-06 16:29:02.634 [INFO ] [g.discovery.internal.PersistentInbox] - Added new thing 'avmfritz:fritzbox:192_168_178_12' to inbox.
2021-03-06 16:29:39.512 [TRACE] [rver.impl.http.impl.AccessoryHandler] - Terminated HomeKit connection from /192.168.178.20:49175
2021-03-06 16:31:11.304 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 831172396
2021-03-06 16:32:36.114 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 216672649
2021-03-06 16:33:10.759 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 358001090
2021-03-06 16:33:46.964 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 16:34:55.519 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 129206442
2021-03-06 16:45:40.512 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 216672649
2021-03-06 16:47:01.722 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 831172396
2021-03-06 16:47:36.061 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 216672649
2021-03-06 16:48:10.682 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 358001090
2021-03-06 16:48:46.865 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 16:49:55.443 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 129206442
2021-03-06 16:50:02.509 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 701146560
2021-03-06 16:50:08.295 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1466450999
2021-03-06 16:53:45.820 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1695172482
2021-03-06 16:55:21.952 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1466450999
2021-03-06 16:56:38.609 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 701146560
2021-03-06 16:57:53.823 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 129206442
2021-03-06 17:00:33.810 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 129206442
2021-03-06 17:01:25.651 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 17:02:01.612 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 831172396
2021-03-06 17:02:08.794 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 129206442
2021-03-06 17:02:35.995 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 216672649
2021-03-06 17:03:10.623 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 358001090
2021-03-06 17:03:34.633 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 17:03:38.338 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Exception in binary handler
java.io.IOException: Connection reset by peer
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
	at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:247) ~[bundleFile:4.1.42.Final]
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1147) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:635) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:552) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514) [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:834) [?:?]
2021-03-06 17:03:38.346 [DEBUG] [rver.impl.http.impl.AccessoryHandler] - Exception caught in web handler
java.io.IOException: Connection reset by peer
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
	at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:247) ~[bundleFile:4.1.42.Final]
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1147) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:635) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:552) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514) ~[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:834) [?:?]
2021-03-06 17:03:38.354 [TRACE] [rver.impl.http.impl.AccessoryHandler] - Terminated HomeKit connection from /192.168.178.4:60090
2021-03-06 17:04:06.778 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 129206442
2021-03-06 17:04:55.313 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 129206442
2021-03-06 17:05:08.273 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1466450999
2021-03-06 17:06:43.258 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 129206442
2021-03-06 17:09:01.631 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 17:11:06.722 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 268272700
2021-03-06 17:11:10.256 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 268272700
2021-03-06 17:11:21.865 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1273062571
2021-03-06 17:11:21.869 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1273062571
2021-03-06 17:11:21.871 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1273062571
2021-03-06 17:11:22.014 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1273062571
2021-03-06 17:11:22.017 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1273062571
2021-03-06 17:11:22.023 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1273062571
2021-03-06 17:11:24.542 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 165438509
2021-03-06 17:11:24.546 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 165438509
2021-03-06 17:11:24.550 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 165438509
2021-03-06 17:11:49.438 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined
2021-03-06 17:12:06.529 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined
2021-03-06 17:12:24.914 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1466450999
2021-03-06 17:15:00.913 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1695172482
2021-03-06 17:17:01.563 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 831172396
2021-03-06 17:17:35.974 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 216672649
2021-03-06 17:18:10.555 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 358001090
2021-03-06 17:18:46.730 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 17:18:53.905 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 216672649
2021-03-06 17:19:55.214 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 129206442
2021-03-06 17:20:02.406 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 701146560
2021-03-06 17:20:08.153 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1466450999
2021-03-06 17:21:04.111 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 17:24:44.582 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 17:28:14.381 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 216672649
2021-03-06 17:28:23.597 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 17:32:35.860 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 216672649
2021-03-06 17:33:30.329 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Exception in binary handler
java.io.IOException: Connection reset by peer
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
	at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:247) ~[bundleFile:4.1.42.Final]
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1147) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:635) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:552) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514) [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:834) [?:?]
2021-03-06 17:33:30.339 [DEBUG] [rver.impl.http.impl.AccessoryHandler] - Exception caught in web handler
java.io.IOException: Connection reset by peer
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
	at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:247) ~[bundleFile:4.1.42.Final]
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1147) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:635) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:552) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514) ~[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:834) [?:?]
2021-03-06 17:33:30.345 [TRACE] [rver.impl.http.impl.AccessoryHandler] - Terminated HomeKit connection from /192.168.178.18:51054
2021-03-06 17:33:46.695 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 17:34:26.081 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 17:34:55.111 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 129206442
2021-03-06 17:35:02.342 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 701146560
2021-03-06 17:35:08.079 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1466450999
2021-03-06 17:35:14.427 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1695172482
2021-03-06 17:35:14.889 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1695172792
2021-03-06 17:36:06.972 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 701146560
2021-03-06 17:36:49.844 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1466450999
2021-03-06 17:37:19.776 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined
2021-03-06 17:40:24.839 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1695172482
2021-03-06 17:41:09.610 [WARN ] [e.internal.SseItemStatesEventBuilder] - Attempting to send a state update of an item which doesn't exist: undefined
2021-03-06 17:41:53.779 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1695172792
2021-03-06 17:42:31.870 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 216672649
2021-03-06 17:44:30.887 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 831172396
2021-03-06 17:44:31.541 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 17:48:10.412 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 358001090
2021-03-06 17:48:46.607 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-06 17:49:55.059 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 129206442
2021-03-06 17:50:00.348 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1466450999
2021-03-06 17:50:07.986 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1466450999

from the log it looks like a network issues. it says that other side - the home app - reset the connection or is not reachable.

why connection issue could happen, homekit bundle should be actually be able to recover from it and work again once the connection stable again. but this seems to be not the case - once connection is lost it does not try to re-establish it again.

for now the only fix would be to make connection more stable. maybe some of the components, e.g. openhab, get into sleep mode.

Hi Eugen,

since I changed from dual stack to IPv4 only on my QNAP NAS, the docker container has only IPv4 IP address assign.
This seems to had solve the problem - at least HomeKit is stable now for more than 12 hours.

1 Like

i can confirm this so far.

1 Like

Unfortunately, setting java parameter -Djava.net.preferIPv4Stack=true did not solve the issue for me.
Yesterday afternoon, the connection broke until my nightly reboot at 3:00.
In the morning, I observed the following situation, that the connection broke and then healed itself shortly after that by logging New HomeKit connection from /192.168.178.4:62457


2021-03-09 08:42:54.041 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Received data [/192.168.178.20:49205]:
PUT /characteristics HTTP/1.1
Host: openHAB._hap._tcp.local
Content-Length: 58
Content-Type: application/hap+json

{"characteristics":[{"aid":941188179,"iid":9,"ev":false}]}
2021-03-09 08:42:54.046 [TRACE] [impl.connections.SubscriptionManager] - Removed subscription to class io.github.hapjava.characteristics.impl.common.OnCharacteristic for 15153598
2021-03-09 08:42:54.047 [TRACE] [er.impl.http.HomekitClientConnection] - 204 /characteristics
2021-03-09 08:42:54.049 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Sending data [/192.168.178.20:49205]:
HTTP/1.1 204 No Content
Content-type: application/hap+json
Connection: keep-alive


2021-03-09 08:42:54.051 [TRACE] [server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 105, cap: 256) [/192.168.178.20:49205]:
5700281C6B6479EB23BE9BABDAFE4B08BE1F71C05B79C7E035805596864D1EB4463300E10DE1140ABD01EB89C9AC8741ADF5E5D81CA81D5C37851115BC7E29987ABB2B3F9240AE99E2BA96642A86226C42706BD7315251C60330E57E18B4BA6AA646A3B93E91FD9

2021-03-09 08:42:54.065 [TRACE] [server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 234, cap: 368) [/192.168.178.20:49205]:
D80069E78A798D9B81C8E0D8A375EEB84A7D24AC8BD303C560F2EC481D8CB1470D908470F86BF74F4DC5ABA3A10131424A2F02E2E49585C7EE8EEB9B99ADA0E7FF38EE987A451DACECD052B5EC07D585AF43470B1D2A9DC1B973C47C740CDFCB58C1A616508D69565EFF0E168FBAB90A9873E9ECF410869F31C4F97FBA14CB431E7F1C721D8327DC652994790EF724C3528D00D4BE5E411B80F83FA95547E0D34D6AE0943ADE1CAAF2442C9F70354F9EFD25982B492BD7582AEB05B5587697059D052AD7775C6456B0E57E213E3112D8AD10721FFC89F124F71150EBB281E3B32DCB0B60E418E07980D4

2021-03-09 08:42:54.067 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Received message of length 234. Existing buffer is 0
2021-03-09 08:42:54.068 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 234
2021-03-09 08:42:54.070 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Read complete message
2021-03-09 08:42:54.071 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Returning 1 results
2021-03-09 08:42:54.073 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Received data [/192.168.178.20:49205]:
PUT /characteristics HTTP/1.1
Host: openHAB._hap._tcp.local
Content-Length: 96
Content-Type: application/hap+json

{"characteristics":[{"aid":523064110,"iid":10,"ev":false},{"aid":523064110,"iid":9,"ev":false}]}
2021-03-09 08:42:54.076 [TRACE] [impl.connections.SubscriptionManager] - Removed subscription to class io.github.hapjava.characteristics.impl.lightbulb.BrightnessCharacteristic for 15153598
2021-03-09 08:42:54.077 [TRACE] [impl.connections.SubscriptionManager] - Removed subscription to class io.github.hapjava.characteristics.impl.common.OnCharacteristic for 15153598
2021-03-09 08:42:54.078 [TRACE] [er.impl.http.HomekitClientConnection] - 204 /characteristics
2021-03-09 08:42:54.080 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Sending data [/192.168.178.20:49205]:
HTTP/1.1 204 No Content
Content-type: application/hap+json
Connection: keep-alive


2021-03-09 08:42:54.082 [TRACE] [server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 105, cap: 256) [/192.168.178.20:49205]:
57000636B9E4966093A27BFD9E91E170A595C38FD9A8EF15BBEB69D5A2461D349A35734E447FF504C5A98ECCE1E188818628EA2A4916F6E0696A75EE5F39D2B111B22BC3699ED7DB5FBBA06314C6EC66095EF1877DF77BC3A31BDCEF7B7172DD071DA3D19892CA6

2021-03-09 08:43:37.993 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Exception in binary handler
java.io.IOException: Connection reset by peer
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
	at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:247) ~[bundleFile:4.1.42.Final]
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1147) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:635) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:552) [bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514) [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:834) [?:?]
2021-03-09 08:43:37.998 [DEBUG] [rver.impl.http.impl.AccessoryHandler] - Exception caught in web handler
java.io.IOException: Connection reset by peer
	at sun.nio.ch.FileDispatcherImpl.read0(Native Method) ~[?:?]
	at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39) ~[?:?]
	at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:276) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:233) ~[?:?]
	at sun.nio.ch.IOUtil.read(IOUtil.java:223) ~[?:?]
	at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:358) ~[?:?]
	at io.netty.buffer.PooledByteBuf.setBytes(PooledByteBuf.java:247) ~[bundleFile:4.1.42.Final]
	at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1147) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:347) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:148) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:700) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:635) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:552) ~[bundleFile:4.1.42.Final]
	at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:514) ~[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:834) [?:?]
2021-03-09 08:43:38.004 [TRACE] [rver.impl.http.impl.AccessoryHandler] - Terminated HomeKit connection from /192.168.178.8:62301
2021-03-09 08:46:39.774 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 831172396
2021-03-09 08:46:39.781 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Sending data [/192.168.178.17:56683]:
EVENT/1.0 200 OK
Content-type: application/hap+json
Content-Length: 60
Connection: keep-alive

{"characteristics":[{"aid":831172396,"iid":9,"value":19.2}]}
2021-03-09 08:46:39.785 [TRACE] [server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 178, cap: 256) [/192.168.178.17:56683]:
A0004AE426B09856183FB12D257D32C8626C04367180ADDF0172AA0284D69C0DED48D409726E4EF7BC59D51EBB315EED1583A8E3928E3F2E8CFF8CAF096BF70EF2C02C8EAB834B307E7A14E36875F08C88850C161A4776768D53CCF3C36AA707FF9DC37A4E16A3F3DBA33CEA0764141651424FCEC1EA651E5F6F0519FEF8D28F76EA5EE151F571637913A2E4C3A722BED0F6AD427E972BDB735584D80B11C2DA81F54CFEBDDDB4B8084BEB7B802078DAA7D0

2021-03-09 08:47:19.040 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 216672649
2021-03-09 08:47:19.046 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Sending data [/192.168.178.17:56683]:
EVENT/1.0 200 OK
Content-type: application/hap+json
Content-Length: 60
Connection: keep-alive

{"characteristics":[{"aid":216672649,"iid":9,"value":16.7}]}
2021-03-09 08:47:19.048 [TRACE] [server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 178, cap: 256) [/192.168.178.17:56683]:
A00057EE458CAC69909F04029C6A2E3FE28E895B9CADD0AF6FEAB0887420F8F94A518F98344965F3EFCA579636AC0EB00479901C43AA4CE636ED555EA9DA08663F4DFB291217B46781BAE57C545CC6D58EC3EB11AB746A363F40A8ACACE2A5D727AF58572AA8272825C6F61F1C21FF28B8EE7D352118BFAFBBC75F169A5B294728732088881222DFF5F00302E3633F8254F310E61991CC3376236A01CC8FC5D59BED6315CF0B0ECFB886D7A42848D81

2021-03-09 08:47:24.011 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1695172792
2021-03-09 08:47:24.015 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Sending data [/192.168.178.17:56683]:
EVENT/1.0 200 OK
Content-type: application/hap+json
Content-Length: 62
Connection: keep-alive

{"characteristics":[{"aid":1695172792,"iid":9,"value":false}]}
2021-03-09 08:47:24.018 [TRACE] [server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 180, cap: 256) [/192.168.178.17:56683]:
A200B509CECA31CF8E2E735B1BBFF5EDB3CC6DD5EB08FAD8B1A98661DE9C11168B56C78B68B7CCA33569645231D3F122EFDD75A97CADB080409C4CBFAAE299CBE50979401B3F8AD4111D7BF910EF756C2EA60E90D3EC5E6498DD2119E0E53818B314018091EFB329E6F489831F9FA039D42C765007BBF369CF29F1A0AF321920EB82E42EFC6E2D668123F189364E634EE09D3DED11A9CF91BDDFEF9977ECBD494D3795B979A30028D3914017E9A5CA1

2021-03-09 08:48:30.423 [TRACE] [impl.connections.SubscriptionManager] - Publishing change for 1441220483
2021-03-09 08:48:30.425 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Sending data [/192.168.178.17:56683]:
EVENT/1.0 200 OK
Content-type: application/hap+json
Content-Length: 61
Connection: keep-alive

{"characteristics":[{"aid":1441220483,"iid":9,"value":20.8}]}
2021-03-09 08:48:30.427 [TRACE] [server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 179, cap: 256) [/192.168.178.17:56683]:
A100E7856FB04332A45815369740E012087C5B36C51DE8E9BE234F51A7ADB76953B5E50519276F8133153527D0C60138379061BC8BDDA781FC0779BA9A3CBA51B7B4276C03F4040D0183594228ED3CF5F108868C68F2F9940C6C427199E30F55023AF9E043FA2E94111F8109DA3A71C8F007FAC9DEDF25D645A28D47CEE3EE89BF26D4567761569401AFEC28733A68F111AE87E98A2DC6A325EDBFA4EE6E553781B66044F1E9B39A6FB203FF97EA8522583752

2021-03-09 08:48:40.985 [TRACE] [rver.impl.http.impl.AccessoryHandler] - New HomeKit connection from /192.168.178.4:62457
2021-03-09 08:48:40.986 [TRACE] [server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 158, cap: 1024) [/192.168.178.4:62457]:
504F5354202F706169722D76657269667920485454502F312E310D0A486F73743A206F70656E4841422E5F6861702E5F7463702E6C6F63616C0D0A436F6E74656E742D4C656E6774683A2033370D0A436F6E74656E742D547970653A206170706C69636174696F6E2F70616972696E672B746C76380D0A6010103205706EC3883F7B0913D240E6D36989892B125FDB2872EFDA498BCE0CDD6319409

2021-03-09 08:48:40.989 [TRACE] [impl.pairing.PairVerificationManager] - Starting pair verification for openHAB
2021-03-09 08:48:41.008 [TRACE] [er.impl.http.HomekitClientConnection] - 200 /pair-verify
2021-03-09 08:48:41.010 [TRACE] [server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 243, cap: 256) [/192.168.178.4:62457]:
485454502F312E3120323030204F4B0D0A436F6E74656E742D747970653A206170706C69636174696F6E2F70616972696E672B746C76380D0A436F6E74656E742D4C656E6774683A203133390D0A436F6E6E656374696F6E3A206B6565702D616C6976650D0A0D0A0601020564CB98E76F0730F8731D3FF99218F14E3A8B17AB3B8D41B360B776BBEC8CF9FAB0D10E3707A6D3019D18E29571C7A6A0967B1752C2F131464BAFAD1F0AF94A9FFD71EE6D4CB0FED662FF1825359C5620D309A443F129420897E093A23D8224DE504D0B0D1E032096E985DAF29ABD2A6E23E5E18EF0CE81909608C3FC9279B2C5C0DB7129F95430

2021-03-09 08:48:41.054 [TRACE] [server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 247, cap: 1024) [/192.168.178.4:62457]:
504F5354202F706169722D7665726966754502F312E310D0A486F73743A206F70656E4841422E5F6861702E5F7463702E6C6F63616C0D0A436F6E74656E742D4C656E6774683A203132350D0A436F6E74656E742D547970653A206170706C69636174696F6E2F70616972696E672B746C76380D0A0D0A05787D25A55DEBAFC585EEC3B6E9B937B2E3410BDB0312879C5266A1327E9A8318D543F695B5D4AE65135EED51FFDD55E004DC1FC4E26536E9A34F7537FEDF92016D8B1F008255DB84CC0247D8E5A6213CAB6AA5F8E3BAB867D7963E2AACCE8F0BB094ADFB8419AB2E06C27963E6BA95AD0E63E9ACD8D493F1060103

2021-03-09 08:48:41.069 [TRACE] [impl.pairing.PairVerificationManager] - Completed pair verification for openHAB
2021-03-09 08:48:41.071 [TRACE] [er.impl.http.HomekitClientConnection] - 200 /pair-verify
2021-03-09 08:48:41.075 [TRACE] [server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 105, cap: 256) [/192.168.178.4:62457]:
485454502F312E3120323030204F4B0D0A436F6E74656E742D747970653A206170706C69636174696F6E2F70616972696E672B746C76380D0A436F6E74656E742D4C656E6774683A20330D0A436F6E6E656374696F6E3A2065702D616C6976650D0A0D0A060104

2021-03-09 08:48:41.152 [TRACE] [server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 78, cap: 512) [/192.168.178.4:62457]:
3C004B9639BC0AA93EF8860681D1F336F5BCBCFB05F765B73C57E139A464F5B931196FD97DEA36A60B7F3A7778A95BBB1019588596B55C46E12048E1936B5B3CE2E4ABFEBB6269E9BF73963A

2021-03-09 08:48:41.154 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Received message of length 78. Existing buffer is 0
2021-03-09 08:48:41.155 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 78
2021-03-09 08:48:41.156 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Read complete message
2021-03-09 08:48:41.157 [TRACE] [ons.LengthPrefixedByteArrayProcessor] - Returning 1 results
2021-03-09 08:48:41.158 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Received data [/192.168.178.4:62457]:
GET /accessories HTTP/1.1
Host: openHAB._hap._tcp.local


2021-03-09 08:48:41.398 [TRACE] [er.impl.http.HomekitClientConnection] - 200 /accessories
2021-03-09 08:48:41.402 [DEBUG] [.server.impl.http.impl.BinaryHandler] - Sending data [/192.168.178.4:62457]:
HTTP/1.1 200 OK
Content-type: application/hap+json
Content-Length: 46960
Connection: keep-alive

{"accessories":[{"aid":1,"services":[{"iid":1,"type":"3E","characteristics":[{"`

For me neither. Also disabling IPv6 in OH3 network settings didn’t solve it.
Inside the docker Container the eth1 interface had always IPv4 and IPv6 addresses assigned.
However when I disabled the IPv6 Stack on my NAS the Problem was solved.

I have disabled ipv6 in my linux kernel completely where openhab runs… lets see if it helps. Re-established all accessories again in Home App, for now few hours — works ok

Thanks

This workaround still is very reliable. No disconnects since that here with my setup. Does this need to be a permanent solutions or will there be a fix at some point?

if you dont need ipv6 i would keep it disabled. it can create headaches not only with openHAB.
i have also committed a fix that use the “old” logic for mDNS

maybe it will help to keep ipv6 enabled.
it is not merged yet, so you cannot test yet

IPv6 seems to be the problem (well or how ipv6 is handled in OH/homekit-binding). More than 24h — no issues so far

1 Like