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
Lets fingers crossed
Update: After almost 6hours the HomeKit connection failed again
I hope @yfre can support to solve the problem soon.
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)
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
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!
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
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.
i can confirm this so far.
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