Homekit items showing "no response" in Home app after OH upgrade (3.0 -> 3.0.1)

Add-ons Other
1

I was running OH3 stable and using OpenHABian I updated to OH3.0.1. OH runs on a RPi 3b+.
After the update all my homekit items are coming up as “no response”. I have restarted the homekit bundle, restarted OH, rebooted the Pi, but I couldn’t get the items to come back online. Ultimately I removed and re-added the bridge, but I had to them re-arrange everything again.

I had a hell of a time getting homekit to work and eventually the only way I could do it was to reflash OH3 on to a new SD card, so I’m used to a bit of difficulty with homekit.

Anyway I’m not sure why I’m writing this - I suppose to see if this has happened to others and to see if they were able to recover from the situation without having to remove the bridge. It may also signify a bug with the integration and I would be happy to submit an issue if its not a once-off. Below are 2 sets of logs, after restarting OH whilst the items were showing “no response” and after removing and then readding the bridge. The line which reads 15:27:42.582 [TRACE] [erver.impl.http.impl.AccessoryHandler] - New HomeKit connection from /192.168.1.40:58533 is interesting (for me, maybe doesn’t mean anything) but I wondered whether there was a problem with the connection to the phone somehow being dropped and then not recognised after the upgrade.

log when restarting OH with homekit items showing “no response”

openhab> log:tail io.github.hapjava
14:23:08.263 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@22720[Completed normally]
14:23:08.280 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@3ffa07[Completed normally]
14:23:08.306 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@dc8be1[Completed normally]
14:23:08.330 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@1b1b818[Completed normally]
14:23:08.355 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@4fa2e9[Completed normally]
14:23:08.377 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@1999165[Completed normally]
14:23:08.391 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@1e08874[Completed normally]
14:23:08.400 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@12b8728[Completed normally]
14:23:08.410 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@fc244e[Completed normally]
14:23:08.422 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@1e98f0d[Completed normally]
14:23:08.432 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@7f042c[Completed normally]
14:23:08.443 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@1bad70c[Completed normally]
14:23:08.455 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@814121[Completed normally]
14:23:11.397 [TRACE] [mpl.http.impl.NettyHomekitHttpService] - Bound homekit listener to /192.168.1.127:9124
14:23:11.426 [TRACE] [ver.impl.jmdns.JmdnsHomekitAdvertiser] - Advertising accessory openHAB
14:23:11.435 [INFO ] [ver.impl.jmdns.JmdnsHomekitAdvertiser] - Registering _hap._tcp.local. on port 9124
14:36:22.496 [TRACE] [ver.impl.jmdns.JmdnsHomekitAdvertiser] - Re-creating service due to change in configuration index to 57
14:36:24.507 [INFO ] [ver.impl.jmdns.JmdnsHomekitAdvertiser] - Registering _hap._tcp.local. on port 9124

log while restarting OH after I readded the bridge to the Home app (i restarted to make sure that the connection survived rebooting the Pi):

openhab> log:tail io.github.hapjava
15:27:33.394 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@7c18b6[Completed normally]
15:27:33.423 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@7a739e[Completed normally]
15:27:33.498 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@39ca80[Completed normally]
15:27:33.524 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@d2c7d9[Completed normally]
15:27:33.549 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@11162dc[Completed normally]
15:27:33.596 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@4c0e23[Completed normally]
15:27:33.622 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@db7e0[Completed normally]
15:27:33.649 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@c74f37[Completed normally]
15:27:33.676 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@4d5b1[Completed normally]
15:27:33.746 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@adf9c4[Completed normally]
15:27:33.788 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@1aae946[Completed normally]
15:27:33.823 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@1d0a3f3[Completed normally]
15:27:33.853 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@1654ce5[Completed normally]
15:27:33.872 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@c7ee94[Completed normally]
15:27:33.890 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@6bd753[Completed normally]
15:27:33.909 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@fe2a56[Completed normally]
15:27:33.928 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@1154e48[Completed normally]
15:27:33.945 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@9bac30[Completed normally]
15:27:33.961 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@5a2a3f[Completed normally]
15:27:33.978 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@11306f8[Completed normally]
15:27:33.993 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@23691c[Completed normally]
15:27:34.014 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@1c4b344[Completed normally]
15:27:34.046 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@ce6551[Completed normally]
15:27:34.068 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@14788b6[Completed normally]
15:27:34.099 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@55704b[Completed normally]
15:27:34.129 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@51a8d6[Completed normally]
15:27:34.142 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@1b8bf60[Completed normally]
15:27:34.154 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@559a59[Completed normally]
15:27:34.165 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@1836770[Completed normally]
15:27:34.178 [TRACE] [ithub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@e96ace[Completed normally]
15:27:37.564 [TRACE] [mpl.http.impl.NettyHomekitHttpService] - Bound homekit listener to /192.168.1.127:9124
15:27:37.606 [TRACE] [ver.impl.jmdns.JmdnsHomekitAdvertiser] - Advertising accessory openHAB
15:27:37.617 [INFO ] [ver.impl.jmdns.JmdnsHomekitAdvertiser] - Registering _hap._tcp.local. on port 9124
15:27:42.582 [TRACE] [erver.impl.http.impl.AccessoryHandler] - New HomeKit connection from /192.168.1.40:58533
15:27:42.746 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 158, cap: 1024) [/192.168.1.40:58533]:
504F5354202F706169722D76657269667920485454502F312E310D0A486F73743A206F70656E4841422E5F6861702E5F7463702E6C6F63616C0D0A436F6E74656E742D4C656E6774683A2033370D0A436F6E74656E742D547970653A206170706C69636174696F6E2F70616972696E672B746C76380D0A0D0A060101032091C9DC57A7C6B114B3DD8B227FD084F0E27D1693FD7EA652D809038AF064DE0A

15:27:43.166 [TRACE] [.impl.pairing.PairVerificationManager] - Starting pair verification for openHAB
15:27:44.132 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /pair-verify
15:27:44.202 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 244, cap: 256) [/192.168.1.40:58533]:
485454502F312E3120323030204F4B0D0A436F6E74656E742D747970653A206170706C69636174696F6E2F70616972696E672B746C76380D0A436F6E74656E742D4C656E6774683A203134300D0A436F6E6E656374696F6E3A206B6565702D616C6976650D0A0D0A06010205656F665249E283594226590AC56ABBE12CF3A65446A33EC47B9C8ADC43261D0FBDB900257A5F66E550F69C64ABDC1E850611A5C6FC3B216DF98B9EEECE2935927CBFC26DFD186D65E9E88950D2C43F39FD63AFE3FE48D29B889FC4F571ACB72552A2BD592D64032066CF60826D43DA0D47C70433584F9FD8651113F3117471F51B0ECA1BD467667A

15:27:44.293 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 247, cap: 1024) [/192.168.1.40:58533]:
504F5354202F706169722D76657269667920485454502F312E310D0A486F73743A206F70656E4841422E5F6861702E5F7463702E6C6F63616C0D0A436F6E74656E742D4C656E6774683A203132350D0A436F6E74656E742D547970653A206170706C69636174696F6E2F70616972696E672B746C76380D0A0D0A05785647156213F80F8C450C7B57687670B232159C00A3670ABD3AB206374D88CD1D33EB885864992B4BA43D2C8F48E81D41F090E0D93BC83BE891FBBC05D4E25700E5504CC4A76BA867E012883EBE2E552FF1BEA579786D2844001A26939BA4212984B672047AF4D86A1C7E51133E38611AFF0F8A6FFD5D37D4060103

15:27:44.352 [TRACE] [.impl.pairing.PairVerificationManager] - Completed pair verification for openHAB
15:27:44.381 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /pair-verify
15:27:44.415 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 105, cap: 256) [/192.168.1.40:58533]:
485454502F312E3120323030204F4B0D0A436F6E74656E742D747970653A206170706C69636174696F6E2F70616972696E672B746C76380D0A436F6E74656E742D4C656E6774683A20330D0A436F6E6E656374696F6E3A206B6565702D616C6976650D0A0D0A060104

15:27:44.478 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 78, cap: 512) [/192.168.1.40:58533]:
3C00B4580CBF6CC71941984E218685A4AF0F36E7CC5D6611DB85E331BD5FF5F012387F767AA05ABD7D799655D45C7BF1CC907CCC43C1A085C48FCD30FA10C4E1C59F58D28DCABE1BF189E72AEFB3

15:27:44.503 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 78. Existing buffer is 0
15:27:44.512 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 78
15:27:44.520 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:44.530 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:45.891 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /accessories
15:27:46.123 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 32232, cap: 32768) [/192.168.1.40:58533]:
0004F6EE8B2A52AA886B4A0B0374D19CB761B5B833A318C9FAE8F1DC3701A6A5DC838594F66D8E5A22729E66D5A679DB0239917E2C854DEBF80963CF45FA4AFEA5E0AA7D33B9F088540F4E9AB9BE7FE9034B9572686F7B7EB5D3B9051B8FA0EA68444D569E263F9D35DC7834E685C8FA7388843DD30FA8B778A2D5E4A31FC312687D5ECDE4242D3AC74D06053183679DBDCC71BA16D9C
^ - super huge line of gibberish which I removed so that I could post this

15:27:47.016 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 98, cap: 512) [/192.168.1.40:58533]:
5000C4ED327DA329A4C8734263995A775AD2C8DB291E560ABDAD14572C72F69903A1598D2B05E29C6A0C678997D7D813CF72063B465E4DFB6229506F0236EC7C132FF6013954BA8AE754DB294CF2775891FB173F5B5C34A95CC9A115A8BFBBE8262D

15:27:47.027 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 98. Existing buffer is 0
15:27:47.035 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 98
15:27:47.042 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:47.049 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:47.068 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=1605298282.7
15:27:47.079 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 180, cap: 256) [/192.168.1.40:58533]:
A20039F07067DCB1C6D907DAE971C7F550C3FFC75025A42545A3E50FCEAFA13720B389DC3A838427BF4462B2575EF06D412C645B1E598B4120D3C8676B76B4D3AFD65D504E6E80206F9B6DA09A723A473AE71984F2878F75C23F13D7C5E3966DD30FA2311EE926561A79ABBC17289EDBBCFDCEA0B94C4775ED24F216CC8EB69BA677D35C6D3516994178E2D2EEF376EE08471B38680F4C9570EEAB83ECDB6D797142F15338CAAAA4A7749EE7260D3E1D1C7165D1

15:27:47.141 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 232, cap: 496) [/192.168.1.40:58533]:
D60028BC5114DE6BD147531B855A5F1F21BBD2A0FF7CA24B92FFC3680E2B5ABA4AF1A67AE83A8F15819752736BCB6809F4793683C19185B36565E46096CA72434D3FEADE36682E5C166F20745F2308EBA8780B6F20EB6179395DDA9F7B3CF80675DBDB7931418539EDEC44D1A9ECEC71434B1671EA7C01B5A25437A6BD3EF8ABC05F1B75D807E948CF1B63F327DCAC783E172DFFEC542C49BFEFDE0C59555F31D5A8308BCC39B387470FC1368FEAC93D5E0185741ADCF968D2FC2163B0395E985D2E1419520F286B0F7F9DF0743769214DCE49EAF9AC4E78544FF6E84177F1B21EE8EA3FB927B878

15:27:47.153 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 232. Existing buffer is 0
15:27:47.173 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 232
15:27:47.181 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:47.189 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:47.317 [TRACE] [.impl.connections.SubscriptionManager] - Added subscription to class io.github.hapjava.characteristics.impl.garagedoor.CurrentDoorStateCharacteristic for 27386449
15:27:47.324 [TRACE] [.impl.connections.SubscriptionManager] - Added subscription to class io.github.hapjava.characteristics.impl.garagedoor.TargetDoorStateCharacteristic for 27386449
15:27:47.335 [TRACE] [ver.impl.http.HomekitClientConnection] - 204 /characteristics
15:27:47.345 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 105, cap: 256) [/192.168.1.40:58533]:
57008BD601FF17EC8A25451975DFF014DA53A448BCC178D873904E3A0AA2DE6BBF80EA575288825FDFC46EEF38E17DE0C735A4BBA74D1159233997BF78A1EF849718ED31BD9E16EA7731C5392E999A07666FD47F3B073F3EC4B33528518EF706617760488862DE54F0

15:27:47.444 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 98, cap: 496) [/192.168.1.40:58533]:
500093462CCA45CCCFAA4671FE50A5B9BF697CF3D02EB231137F1B02637C041E98868CFA351037B3A9485ECA4FB6281A4830EDB3633716DF7C675EC022C75CC07C59F47A3EF38CAD771FA6BF4A0F8CD2756440B0A13E53808B922548E5D854053305

15:27:47.453 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 98. Existing buffer is 0
15:27:47.460 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 98
15:27:47.469 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:47.477 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:47.495 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=1021861654.7
15:27:47.506 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 180, cap: 256) [/192.168.1.40:58533]:
A200B2B1FC5F3A1DA6505ABBA2EF5E4F66C441692CD6690781AC324264D1148D61125621026763197B14D11B91FAF74191A81B4E3696BF093314AA5BCED0837C39A82D6F927A8F81B7409D5D9D48C26EB5B4AD1FB91984A5DAF272546299E3046A539FC6D6D8D41E7B829BC29A49A9545D4B43B3397779F60F365071DFC6C3DA3FD71578F1799A1925DE43B527B4D0E499DEB76D1F41CE502DCD3EA9AAC7DD3BE2CEC0DAED37BEBC8DFE11B66820F2928C450A9B

15:27:47.568 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 97, cap: 480) [/192.168.1.40:58533]:
4F00B871FC5935C6D94A85F6F7ABED85EC8DE7E2351BF6F6491E24A38384719317BF875BBAF58823AA4040DE24ACB18AF32F4FA4E83C655F707D1B765202441EE71DCB4DFEC3EBF5A136487FF1FE532CF29A41791274FA0D5169E36C3341EC7344

15:27:47.577 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 97. Existing buffer is 0
15:27:47.589 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 97
15:27:47.597 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:47.605 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:47.620 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=441422449.7
15:27:47.634 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 179, cap: 256) [/192.168.1.40:58533]:
A1002DE0FB6D677E3E6500AEDBD81966AAFBC6A95270990D170E35C87599C0B01754D2B9C340222CDE3FFE0537AEEF4C7BC7CCF0C132AF814821094D0516E601678B377716CD8D76AE28ABC7AEFF076198345274C37977BC813934EE90FB1F0DFF15FABF6D27CBFE9A2BFCE1037432D6542F9E89C2A9B8B705598A450499C8B3F10A14172FB5D99A02B08D25B7A3638612989AF1B3A7D342E0F92AFEC99FEA7910C61577432C15D574F5D03C22EE6BA76B47F6

15:27:47.753 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 97, cap: 480) [/192.168.1.40:58533]:
4F00BD477F7F3F1458111FAF19607CCC86CB23D5007CD825F3AE42AB2AE88EAAF969A22B9A01B997BBF031C52EC519EA1CF25AC1CF98FE4CB02482FF6714F7EE017BE96403A379ABDA724DDDE344B6EB41AAD29B3E69D1410FC7869C108468008A

15:27:47.764 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 97. Existing buffer is 0
15:27:47.772 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 97
15:27:47.782 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:47.797 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:47.810 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=434010249.7
15:27:47.832 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 179, cap: 256) [/192.168.1.40:58533]:
A1009A1C9C9BE7726D67CD055C883AA1F6D45D867798B4605E9BB70BEB62ED4D2371DF0B44D59D4B9E272312BD297950017A2D9043B3249A63876BE10000408E2E44BE9B86DCB6F989CABCA649CB2D6CBA958EC04A8D820EC90A6AE851A6BACC3C2C00983140C7F3F732BAA7DF784B3B0ED3E0411D7E9DD6667D71E5B8A12C0D988059FEBCC7CADB2731A23FCE86749BCA2579A7A0C566F1295EB5580A474C8183D85CD9EB02A9196CBCED6393722DAF401713

15:27:47.973 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 97, cap: 464) [/192.168.1.40:58533]:
4F0010FC81D77CEDE92DF4E1CA830CDF297E13F5BA918D209D0DBFE5E97F9DA8CF0DCC194883146C07F9BF398EAAD8E1348F8C62C93377979E1515EE114918496152BA1D9C0805B38900BC1EDE96412929BDE290D328E536A8D24B0304B1F480F8

15:27:47.980 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 97. Existing buffer is 0
15:27:47.989 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 97
15:27:47.995 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:48.002 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:48.014 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=432195952.7
15:27:48.036 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 179, cap: 256) [/192.168.1.40:58533]:
A1003A7189B202E8555040A515326A4EA725D2A8B631B1C1415EF6E52FEB36009007A5B8F5936652FF722198D295058C8D48166A65965FFBB878EACABDAF7E51BC5D640D842E77061669B6DAF6BE5AC820877C4CFE5CE86416BB33885D9E9C1FECC4B2BD28F3465CCC55B789C1B05F4FD4408516728984038F49FF83229671FB26403A37EA22FF9D9CFD37886726C89089FA6574F6B81CEB5DC35F3F61B6F6F3D9CBA1FD1F405493CDEA115EF008D8B00FFF76

15:27:48.049 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 97, cap: 464) [/192.168.1.40:58533]:
4F002048D5F0159BA27EB6921BAD82622898C0201580C839FAEA9FA7AAEAE9EF5AF6E1D0B085E4FB024449540576BD88ECDC2CCAA064AC91C250538F0822E98B1C884F23903B521ADDC64D9C24C102ADD3B4229B63A80DC2087DC837431276713B

15:27:48.056 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 97. Existing buffer is 0
15:27:48.062 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 97
15:27:48.086 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:48.103 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:48.128 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=379170450.7
15:27:48.144 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 179, cap: 256) [/192.168.1.40:58533]:
A1007DC26DCFD804AE3156CE0548BB880DB09CFF1202F6F76B17585E4FBBF73F758387FF3F559FE10F77573223041B59193C0F8BB0EC1468B9FDDAAC3F41FBDEFBEFC7E30BC3608AC9A7317467654BD4041D16D12028FE4317E0631C8D9505A77473160EEC3BE746738A6FDA8699A9740330C2A490F94BC3A2BE034543FF536A17AA5014A48C5305FC9161C6C8EC3D7AACFD01DAF4972FB53910E14F5CECB7E36CD39F2E0BE2291DF9CD418F8C41563DF02B61

15:27:48.161 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 97, cap: 448) [/192.168.1.40:58533]:
4F0091A6FFD92AD1609E6147DBDC980852D4B7EEA41AFE3745EAC937C4DA2C3C4AFA0995B3B4E1F32569A68A347DA8181C8D6DBC8DA90EBB04FC8E178EFF78B83FE2D7F7DDDD4851B8A52B4DA7A29D2BE7FAE4C78870B8C8CF204D9D0A7F51FBEF

15:27:48.172 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 97. Existing buffer is 0
15:27:48.181 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 97
15:27:48.188 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:48.195 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:48.208 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=912327783.7
15:27:48.223 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 179, cap: 256) [/192.168.1.40:58533]:
A1008E77A745F27FE661272CF190D24CD3A065EED037F48D57CF4739759FBAB10444FCE32E9E71FE25C30FF2F40EC98B9235ED5E49A5BC5AFACEAF668CEC3A398CD898E73FAD152D6A07F6C819A2E76AF6169740B9D60D1480186B1DC1A3C7CAE2475D001C8640F4DB3B1D98369F3CAB3C862CA75631C45FD719130E64DA1D2FAAEB58835258D5E0C2F6F11A0B0A1C30A05AEA92F6D7A08F4CD6F46D279A4FB2E14FD5EDBDD2C8D5BA36C984868D986AF685E9

15:27:48.239 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 98, cap: 448) [/192.168.1.40:58533]:
50000D293AFAD9F0459E3CE410D6AB2C68DBFAE7D92FAA7F82DDADB2E4562A98D711BC27AA584AA353E2AAA511D457E7C1A37DB6394BAD1E449561F593D18BB067E350E7D5CA7BE9C86CEEDD594B04C25C8A7FF25CB35C0F82B60C0E73F74DCE3C4A

15:27:48.246 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 98. Existing buffer is 0
15:27:48.253 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 98
15:27:48.260 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:48.267 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:48.281 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=1161241609.7
15:27:48.291 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 180, cap: 256) [/192.168.1.40:58533]:
A20025941DC9F14E612DD24FB4630A5AB7D03121DEBD1480F39FDACF65BB9A52774243F9C7C392B7BB5C584713349EA6A359DB208AFDA67351A141C11A8F4C9794D375A07654B7464F117A5C9F41DF27A1692C251E03FD109E9EE9CFF1B55ECF5C624B67383E659E168382FA3567E742020157F49C59E808094EAFE2C94CD0D03591EE023A9CD4B8B148B19D44FF4A7C400490E7FD6CEAB560F80A562012C1FC5702633133DD39DD9D2F9C66597EDFFB95D8885A

15:27:48.304 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 98, cap: 432) [/192.168.1.40:58533]:
500057898CA3CFC10FE39B285D56791CAA9F06B2BD92D8726E1499088F956E499E1CEE3479918E7B750385C1AFA65720168F1A4516DECD7983BCE93F3FD33927C58327BF4667066DD1B43BC95C08F68A7C0449B3ED82085BDE27D21C1822F6AEF857

15:27:48.311 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 98. Existing buffer is 0
15:27:48.318 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 98
15:27:48.324 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:48.330 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:48.344 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=2070064268.7
15:27:48.359 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 180, cap: 256) [/192.168.1.40:58533]:
A2003A8D0EAFB5D666E30E176E5A704562A3157FDDDEDD902CBA10ADADBA833BEFF647BF3228DF01C5964718EAC3056128CC29AE95B978EEDEC6385690F1A700E804A878B5AE6A3EE04AA772151A4877E1E0A5E26DB20E548C4163C5687E3CB22C0F88168689EA3642D570FEFC3A9C3CECF07E8540157B42E28DDB980816C515F908DA4BDCA197028D728F4C69BDCCC1C83AC6B659481A5F159D75A112F5608DDA968CFAED9FF0D2D52F25B9C1D18BC3F2BE33C5

15:27:48.371 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 98, cap: 432) [/192.168.1.40:58533]:
50006CD0217722718993F6FB72CA2C637FBA32681FCF15C37F618C2C581E9CE0F0CF952845980D6CBAB3217E2CBB2CE7ACB5438E68BF02DBE7D762D92659614D997F70FE02762896EB038E47EA2F8ADF07AEE102D8C9EBD34C433A6123B629A1BA9A

15:27:48.378 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 98. Existing buffer is 0
15:27:48.385 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 98
15:27:48.391 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:48.397 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:48.410 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=1403658907.7
15:27:48.426 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 180, cap: 256) [/192.168.1.40:58533]:
A200D3C1966D86D67CD55BD1D481373DB37559BE9155BC3B4B87F88D9F8200A0A184F77A80858A4466BF6D5E2683031C0B6271DD7959B5AB9903F0A831000A8E7256F816C1A505B036285F7EC52350F30B73E4A1B07F9E3050A5DE4B16C2EA10D277354CA7F1C2A91904B291065F2F5165A2DFEAF4F03DD4898501C0A9F95229DCD1AC63650A986EDF0BE1E7181BF001370A849A4B2C02EAC30C8336B8569885B612B03CDFA014FB0AAD2D871CF1CF183406994B

15:27:48.439 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 97, cap: 416) [/192.168.1.40:58533]:
4F00B3F0E01BF98BB525AF3BB15A1FD312B875124537260009E2E0F000DF571635FF75CD169E8FC53BEAB2BC849A432563B12857E36E11D873520D9627B241F8118931B3A517763860B7CAFD32A2727B2BAB4E7A0C79D6094247458D40B2129067

15:27:48.447 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 97. Existing buffer is 0
15:27:48.453 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 97
15:27:48.460 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:48.466 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:48.479 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=781003080.7
15:27:48.489 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 179, cap: 256) [/192.168.1.40:58533]:
A100D3B72C192FDA14BC9EBDDD79ED819295A0BEBAE08066B180E2315C7ACC831051E503D9FFAA0ABE89068A01ED332AF539407803C3E1E943208CA11D8A98C9B0112BB6A5234DD0A71F7805EBD0D9B53255EEC9188E1BB430846B44D40A95C63BB132AA249683E8EB7383C6AE2D61639638D028BE9A8B4B57D1733109B69137DA8949566A04658DDB88F8B4025CED56FEBCB2DFC70BB23ED3F5B6D6AA34ACD7D975193A2E18770D11A93F4197CB5409C392F4

15:27:48.515 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 98, cap: 416) [/192.168.1.40:58533]:
50002A83943B72FBBEB4DA2F55F9317CA76F8471E09DABFB315DBA9AC4724172561CA8F0B8DB6700C978539D4A2678222554B2C09A2DC74F144987010D8289A356306FBE462D0D92CA4A50065CFBF8925C8C106AD42B5F3213FFE677EF9AFB6EBCDD

15:27:48.522 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 98. Existing buffer is 0
15:27:48.529 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 98
15:27:48.535 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:48.543 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:48.556 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=1296401708.7
15:27:48.566 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 180, cap: 256) [/192.168.1.40:58533]:
A200FB1D3C567803A922F556EC6020E9EE026438144D7EA9867BDCE39DBDD964681CCC347D16007D0B7D1D24C8E96E80A3CDBABE589F36A6132011797A39E15AA4F05CB2785680C79A0FDC635F44CADC17D52DDA819054B6C3BFD4A455695C7C486CDF641A4C614C2A6026F51423227A52F3FA5649275FC797B1912BE6A42DFF458D31E25260738F5A079FEEE764772FD28082EFFC7B9132557A2097ED786EAFF5B262885DA12191B5A0308E39318FAD0EA013F4

15:27:48.585 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 98, cap: 400) [/192.168.1.40:58533]:
50007DF0AA282C116D627FEBCE3F50972F583BED72C4C6772061421AA4045A9B673243C6325B17DC27E5167087699164057546C8E787D90D7B62FAFF1F32EBCD0439F11CDB87E0967260CAE2F100AEDB7CFB04E012AAA9450CCC2E6D1BC4DDE1409D

15:27:48.592 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 98. Existing buffer is 0
15:27:48.608 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 98
15:27:48.623 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:48.629 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:48.657 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=1794307723.7
15:27:48.667 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 180, cap: 256) [/192.168.1.40:58533]:
A20042A1973691ECE2963AC86A6785FC509475DC4E05BE9843FEE7F4A02C55DC2E0F5A22E0456F8DCC7A7C9FD9E7DBEF6E5D4D2C029274785198B5427F3B057B6C1E29D41211DE3F08E1C76EE24EB18A727FFB4941DE51109B19D765312758B924EC5FBC02D7AD7BD7CE668322A2727487526B0948984C57892BFDEBEB2EFA3CA34E5553D5E3AC8990D4C01E4E3306C554D8B154C0CB871FEC0DFE53D9731ACF898E53BC38EDD07F60F1C18F3529D5DF7DDCC893

15:27:48.683 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 89, cap: 400) [/192.168.1.40:58533]:
47006DB742C79B74E0ECF471BBF4FFAEE8A45673192BF8EB46EF7B19BA049B02BFCA2D43B8AE94CFBE24671A831D231618D1817998F463705EF7116B596C3934AB73F9C079CA8F59615841E8D5A58759CEE05F07D1451CE70A

15:27:48.690 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 89. Existing buffer is 0
15:27:48.697 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 89
15:27:48.703 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:48.709 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:48.721 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=1.7
15:27:48.735 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 172, cap: 256) [/192.168.1.40:58533]:
9A00FEF53793CF410EDE27F2ECF03BD41F4C4771F44D146FF920927A8E58DD2C4853959CE0FC55DA72F2CF4DE527B2FDE9AE2E9BECBC3708432D128AE8E459876B9C3847359176901F49F4F6B21C4CE1397D2193839DF8753FE5BDF90BE8FA7A115180A235185D5D50E3BD8CBCAB76E5C113B2863F62786331E4F5758543A4EA1B5ED5347058349918C5B63567A3634AFC16630C86FE81A45671CB707D1ED5DE70AA24F61A5E3C32CADCF0FF

15:27:48.749 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 97, cap: 384) [/192.168.1.40:58533]:
4F009F26EA8D229A934C1BC3D59A44C32C321B17C15C34E0D49D03F3D233247BDF19B31C05AFBB05CDE8A50E10AEED227E7641B2D1C13DEA3484834DB40838A36D1180FFBC592459F470E01D850943884B4E955058A5DAEA76B2B34A13E7BFBD7A

15:27:48.756 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 97. Existing buffer is 0
15:27:48.762 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 97
15:27:48.769 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:48.775 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:48.788 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=548386765.7
15:27:48.798 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 179, cap: 256) [/192.168.1.40:58533]:
A1001DF59C51386431CCDBD8664355F6CAEE1E75EF2C368F9EE09A7421234792596BB583CAF71379DB9A2026C74124B7F4E3462EBE21E817D5A387312B0D5E3300FC0D64F911CFCFE89CACBD348112456FBE320A25A621E54B25E39757B39D8D6FB012B20964E5B0DC149D30B45972FF7E4DE5BBFDE2189F984D9356F748EF528B38C434592C898812CC23D94C4BAD1850E4A5A38709F76ECBF8C10C1F9A5050D356A71599668DE5FED1903F7A5FBCB80DD753

15:27:48.811 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 97, cap: 384) [/192.168.1.40:58533]:
4F00349BD49127B4CAA4131106F40F75CF42F54AB06446331118CEFB94E52631848AC632020EED9C0307829D9DCF09681278D718A3102893022DD1A993416C6E664CB39B032914BD25831625A63ADD790F6B7BB2FA68AF7789F48C8035B1A5A703

15:27:48.818 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 97. Existing buffer is 0
15:27:48.825 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 97
15:27:48.831 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:48.859 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:48.879 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=441422448.7
15:27:48.901 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 179, cap: 256) [/192.168.1.40:58533]:
A1003291E0A70F30768C9FA2DF595A4E4FE9F43AF06CAA2A81FEF7AF0438E36679846954B1C16228B465D92A3EF8FD6A26FC8B2621B762F5F46D3E3754CE2802C80B971270B011F59B48D6E7792BA9AE099A0D474E4CEBB21C1172405425F5299E812BF82DB5F25752B1431310C3E6A47C3C5F8D7312A3A8E23DC5AA3B2A3F0D5610E5B66D3681CADBB555DC3D1D81AE2060BE032FBE8C7096362125CCF6550F913112A2DA0C7B58B8922CBBF5E9A867F8A9FD

15:27:48.914 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 98, cap: 368) [/192.168.1.40:58533]:
50007CEED03BFDA656A63A33436B0AE16BEA11EA45EF3B1DBDE37373431B27E527897524964BB3B61B0DAEE285C7303192B9DD6816FD9D25684F2D9DA36C5A8420739F80F648BD316DE8565E46496B8A5647B0087818BC67C4BE72F6BC8DF9F9F2A7

15:27:48.923 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 98. Existing buffer is 0
15:27:48.929 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 98
15:27:48.934 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:48.941 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:48.953 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=2070064265.7
15:27:48.964 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 180, cap: 256) [/192.168.1.40:58533]:
A200A8BC68E3A09EFABDE9479F6DCC87CE4916AC5B37CB8906D4B607B7564E1D61A765B59D784D6DEE4442F218826BA6CE5A8E918F118B50022195FCFB86DBECE4001E57F29600C6F277430E01AF9338B1FAE560175F7A485B7B8664F6B8466C6F7600EEDEB59DB933B84F412785AA1F9737DA2970EC797C8E4C09ECCDC5497F542A547BFED7C62CDE755E7DAA75FB4165CF65C1A9FEFE425ABC4EAFE16DF575EE25FFC25E7F6A003FF551FC5CC8AA57E1553DF0

15:27:48.988 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 98, cap: 368) [/192.168.1.40:58533]:
5000ED043079100F41918B35FC538977A0DE8443F99EA82837A74E93DCF78DD2578F018196405F41CFB0D9CD690B59CE6187CF8814654F26A7DD3AAF6D5E13F1FCEDB213E356110A01E116CB5E6A356EB19CCCFDF48DED191DFCD2E2715EB0D0661A

15:27:48.995 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 98. Existing buffer is 0
15:27:49.002 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 98
15:27:49.013 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:49.019 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:49.036 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=2081565150.7
15:27:49.047 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 180, cap: 256) [/192.168.1.40:58533]:
A2004E18CC66B4A857D119B2CCCD51D510FB8100CC4219E6B5A5D098446F378860B6ABD6C0F5AFBECEF29AD4272801E8271F9BB1FD5B65109913DC07C8296C112956850157A7C450F892628336C49C2534B4A7C984F44B2F31ABCDF97ED56D384BA5CF1284DF22E19B601F6283F5E29865AE010B0712E66A7F062F30EBC26FF5E2AFE917A872D981B5C6B8DD6B0FB63639F1443D19D70ACE15BB882A19280F84BF28F373F39F055A737003799911AE47E0A0CA8E

15:27:49.065 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 98, cap: 352) [/192.168.1.40:58533]:
5000DC736D767CF29F485F576FAFD3F3ADE082C29E9714CA619A253B8FCB806B7E83E0537BA4ED5ED1FA7E5BB80D276FC92605FFAF50790DDFEF3A523F86CC890CB62E9D1F7FE48EFD625362F2785373369B7CAAE9D116FFD94ABDF4333E5E318902

15:27:49.075 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 98. Existing buffer is 0
15:27:49.081 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 98
15:27:49.088 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:49.095 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:49.108 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=2123601125.7
15:27:49.118 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 180, cap: 256) [/192.168.1.40:58533]:
A200E05C8B4943371EE79B522B5E4D531FB95CD7FD24E2462ACAF07F5B75CC0AB4C2326B7AA42900352F590FD00A57B2F0CEFA532845C7D58790401478618E4C460CFF09D01FF8AF1CB305424CDCF917D21A5B6EDC429A49687C20F052E206D9FB4A427A91ED6117208901423C34DF4931CDD7DE180DB1700547345BFB7274F5C5B27376C7A145EE0BF746B62CE393EB9DD02C347D1AD1F303B501A6DF0D32FE163296076059C8974E00AFF7AF817BE584CFDDD5

15:27:49.133 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 98, cap: 352) [/192.168.1.40:58533]:
5000020C4CADDC33EAF3828952590B36A2C25A75FBED6792C384A7B34BF59B2C48D925C39429E9571552BF125C4D5A467AAD1F60E4CDD2206CD367BC3F9CDE97F03694973A7AFCE017A5106619C00B0DDFEFFC274E6082D96EAC27E18B12C152A370

15:27:49.140 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 98. Existing buffer is 0
15:27:49.147 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 98
15:27:49.154 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:49.161 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:49.174 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=2070064269.7
15:27:49.188 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 180, cap: 256) [/192.168.1.40:58533]:
A2007A08DA510FE4B8EEA3B74A4BEED8A609A767EA8CB64F698EF76688113BB5D3B24C376745E986852C003E70259788A6D68705092AE5E1207B04E4FBC83E8E40F17845950E7099BA94C2E09DC72B85ED6456CB56F43F2323DBA6F69090AEA4D8F30B46053E2C458299C571A5FC37BF07C6FE264D50C6AEBBE360364D724E562AF76AD3414ED13CD574030E80817DE8CBC301CC956CF2C992B565DAAE0BF4167CFFCE28D20C01E08734DAE80718B240408F37A6

15:27:49.235 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 97, cap: 336) [/192.168.1.40:58533]:
4F006D2E029865C8A949A7251C19AF90B2522868645A0462F25364C1ABDF8E34A9534C6A47452D6C0156D91837F471D7802583E9862C904CC571E358B6EB793E353944E8E93510C18193551F083A377711E0ABBB39AA495A3E1FAAFAF7D77489FA

15:27:49.249 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 97. Existing buffer is 0
15:27:49.259 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 97
15:27:49.268 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:49.277 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:49.292 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=306306098.7
15:27:49.307 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 179, cap: 256) [/192.168.1.40:58533]:
A10024A23B44FA8AEFA06D2201F640774B44FCBD719277E3288821BE8DFD36266126918D44691836B28EAE8B55836942578DCB3C41B51A424BB96A4DC0AA09D2E7C2C5D2C4C362A1BA14A5BC7AD61E3A7E6558A129A8972D185BC897D636AC2E9451B6723410C84E1C51F1FBC9F4FE6C17D7444D6C6DF73682E1C2C18F0F6EB263F5758AE54CA79715C17ABB98957D324D358E9D218FAF9A5EBA3C86A395CB3A030E37485E902A7190D80A66E9D76DFF2C516B

15:27:49.335 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 98, cap: 336) [/192.168.1.40:58533]:
500097A48C2A747FA067917F48E9E266DD2944807B7A1436645A92B826B7817F42C24F3B9D6F781887E5A415EC38450703015C1160E4A503B055C4A7BC45903C71381E94D26E5008C7BA6E5FCF26F24F12F0ECB1ABB718D2243419D5332DFE57E69E

15:27:49.347 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 98. Existing buffer is 0
15:27:49.356 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 98
15:27:49.364 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:49.373 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:49.387 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=1683908824.7
15:27:49.398 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 180, cap: 256) [/192.168.1.40:58533]:
A2001285EAD313C40F995735B2032BC5A3D36943D6F671EB8D8701F8531053D266E0486F0D60B054AB0D9EBC11374B565E529C99AC7C9326148933FCDDC76684B0D1031C64E8B6E4FCBBFC3C9BFF3CC6BAE4D915FC38E653F0DE90C60C8E1644DA21821CCCC878D8B86F3D482685B283EC1C442FF877B1520521B449050208F4EEE3FDE1FEC2027A86C60033AE3BEC061A0314D02189898C0B3192046C4C145E5F6ACF4AB5B1F92A5BCBABCE207FE19D1494B576

15:27:49.417 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 96, cap: 320) [/192.168.1.40:58533]:
4E00E8A5432816FBFF65B382CA79585C0136207F1F38B9148F2A41CBCB064898522958776E5089377E629967782DCF5D23788473E7E42C5DBB32CFC8C3AC43E1CA63CF8E0AB799C271108BC39A06AE3D2794778E1A66687CE8BF83F8181C256B

15:27:49.428 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 96. Existing buffer is 0
15:27:49.438 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 96
15:27:49.446 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:49.455 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:49.470 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=24824102.7
15:27:49.500 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 178, cap: 256) [/192.168.1.40:58533]:
A00087490CE2C143352245287C29D98F3CE01940A04331B191E557D1098521C1914453E675022BE0B686092638BDBD3FAD50F27D1E83F3EC9CF8B40ECE8897C8340C61F25608A66180BBBD8C17A7819394C27C0E37D9DB23277423192B164C549D9C593B3D64BE484EE91FBCC491857BD672B369911D01C996DF665FDD32F3C8C64CF3048D5558E0BF3A9042333E1B761A01FC8554D5D21D205825107C6EC2FD6C0E76BC788D7E744ED9A41E2DB91C412992

15:27:49.526 [TRACE] [.server.impl.http.impl.LoggingHandler] - READ PooledUnsafeDirectByteBuf(ridx: 0, widx: 98, cap: 320) [/192.168.1.40:58533]:
5000682669C6C92CC44AA2F68AFA6E56DA9B3456E68DAAA38240B7607B7278FB4ABC516D9BF7EB119CF5716BA362DEE207DE7F717803BB03FAF9BC16AE14ABECB1425D78BC169E4AF46BE94791C02774C23BA982EA3148115888344C03DA4476BC08

15:27:49.533 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Received message of length 98. Existing buffer is 0
15:27:49.539 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Attempting to read message of length 98
15:27:49.545 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Read complete message
15:27:49.551 [TRACE] [ions.LengthPrefixedByteArrayProcessor] - Returning 1 results
15:27:49.563 [TRACE] [ver.impl.http.HomekitClientConnection] - 200 /characteristics?id=1385480300.7
15:27:49.576 [TRACE] [.server.impl.http.impl.LoggingHandler] - WRITE PooledUnsafeDirectByteBuf(ridx: 0, widx: 180, cap: 256) [/192.168.1.40:58533]:
A20033AF67170E78EB4DA913A5CA0D90619010377C01699B02DE39265EF8D4FCD9BABC9F34520E5A2454D3D3A13E431794FD8BBC7987096703076B0BB64F9B5D7BB94FE8F96A92CF84DFBB448676505EA351387734C8DA5EE5BC3E33F3A973D53CDCC83EE338EE84BCF75D461E01E80FDABCE4DA558FE55BB6586397F1F39A6EBB91022CDCB8B1BAA826FED539CD5CD57EB69F6F5CAD51626D6B74A646CFAA08329F4E3BF26AE20FEDD838191071CF727BC45700

+ heaps more
2

the logs look actually good. home app requested the list of accessories, got it, and started subscription for updates.

can you check in karaf console that you have only one homekit add on running. if you execute this command in karaf you should only see one homekti

list | grep -i homekit

3

Only 1 instance of the add-on:

openhab> list | grep -i homekit
246 x Active x  80 x 3.0.1                   x openHAB Add-ons :: Bundles :: IO :: Homekit

I noticed this in the release notes for OH 3.1M1 - I wonder if this may have been the cause???

In any event now that 3.1M1 has been released I’ll do an upgrade and see if the issue occurs again

4

I am on snapshot 3.1.0 Build #2169, Synology Docker.

What works is that changes are recognized on the fly, adding or removing homekit items.
What still does not work is if i restart openHAB in the docker, the homekit does not connect again. i need to remove and re-add the openHAB homekit bridge again in the homekit app ( eve app ) and assign the items. Is someone experiencing this as well?

5

can you check whether you have record “user” in jsondb/homekit.json
e.g.

cat /var/lib/openhab2/jsondb/homekit.json
{
  "user_xx:xx:xx:xx:xx:xxx-xxxx-xxxx-xxxx-xxxxxxxxx": {
    "class": "java.lang.String",
    "value": "xxxxxxxxxx"
  },
...
6

I re-added the bridge to homekit and yes, i have 5 user like this. Everything working fine. Should i restart and look again into this file?

“user_6:xx:19:xx:97:751BDDB7F1-xxxx-4E98-xxxx-2F8xxxxxC5”: {
“class”: “java.lang.String”,
“value”: “3xxxXKJxxxx4JZeeRUSxxxxxg7+BxxxxnU\u003d”
},

7

yes, please try and check the file. user = paired device.
so, if users are there, then pairings is still in place and home app should be able to connect

8

This works well now, after a re-start the homekit seems re-connected.

Sometimes i clear cache and tmp files before i re-start. Could this be the root-cause of a missed re-connect? If yes, good to know :slight_smile:

1 Like
9

not sure about impact of cache and tmp files on homekit.json. maybe you can figure it out with try-and-error approach :slight_smile:

10

will do as long as i “just” have 17 homekit items over openHAB it is just a couple of minutes work to re-arrange in EVE. Not time to migrate from homebridge-homematic yet with another 20. Thanks anyway Eugen. Much appreciated

11

I can confirm this. But for me also recognition when new item added doesn’t work.

12

Hello yfre

when I restart the bundle, then the user was removed in homekit.json and this warning occurs:

Could not find existing MAC in org.openhab.core.storage.json.internal.JsonStorage. Generating new MAC. This will require re-pairing of iOS devices.

Can you help?

13

if this happens then you need to re-pair, i.e. remove openhab from home app (if it is still there) and add again.

it should be safe to restart bundle without any re-pairing. it should sore the user in homekit.json permanently. but in your case it looks like homekit.json got completely lost. it is difficult to say, why that happened.

as solution, you could make a copy of homekit.json with the user. you can also check in the /var/lib/openhab2/jsondb/backup/ folder, maybe you have an older version with the user.

14

Thanks yfre for your fast answer. In my case it was an authorization problem. I configured with default user 9001. I reconfigured with my correct ID, deleted all and now it works over restarts of OH.
But: When I delete an item, it will be directly removed in home app, but when I add an new item, it will not be shown in home app. I restart the bundle, it shows an item more, but not in home app.

15

this is known bug. it was fixed in the recently and as part of milestone and snapshot, but it is not in the stable release yet.

16

I’m running the current snapshot version:

openhab> list -s | grep homekit                                                                                      
260 │ Active │  80 │ 3.1.0.202103040346      │ org.openhab.io.homekit
17

ok. then it should create homekit item without restart. how do you add new items? using UI? anything in the log file when you add new item?

18

Yes with UI.

Here some TRACE logs, after these logs there are many many other TRACE data:

2021-03-06 22:44:12.987 [TRACE] [thub.hapjava.server.impl.HomekitRoot] - Added accessory java.util.concurrent.CompletableFuture@2ca63daa[Completed normally]
2021-03-06 22:44:12.989 [TRACE] [pl.http.impl.NettyHomekitHttpService] - Resetting connections
2021-03-06 22:44:12.990 [TRACE] [rver.impl.http.impl.AccessoryHandler] - Terminated HomeKit connection from /192.168.0.55:50428
2021-03-06 22:44:12.992 [TRACE] [rver.impl.http.impl.AccessoryHandler] - Terminated HomeKit connection from /192.168.0.76:51140
2021-03-06 22:44:12.992 [TRACE] [rver.impl.http.impl.AccessoryHandler] - Terminated HomeKit connection from /192.168.0.42:49472
2021-03-06 22:44:12.992 [TRACE] [rver.impl.http.impl.AccessoryHandler] - Terminated HomeKit connection from /192.168.0.73:49275
2021-03-06 22:44:12.995 [TRACE] [er.impl.jmdns.JmdnsHomekitAdvertiser] - Re-creating service due to change in configuration index to 8
2021-03-06 22:44:14.996 [INFO ] [er.impl.jmdns.JmdnsHomekitAdvertiser] - Registering _hap._tcp.local. on port 9123
2021-03-06 22:44:14.997 [TRACE] [er.impl.jmdns.JmdnsHomekitAdvertiser] - MAC:fa:a9:d5:f1:d:53 Setup Id:R3F2
2021-03-06 22:44:16.666 [TRACE] [rver.impl.http.impl.AccessoryHandler] - New HomeKit connection from /192.168.0.55:50647
19

the log looks perfect, it detects new item, terminate the connection to home app clients, update the configuration number and inform client about the change . the new item should appear in the home app 2-3 seconds after you saved it.
from the log i dont see any issue on openhab side

20

Thanks yfre for analysis. I did a complete nee setup and now it works as aspected.

1 Like