Devices become unresponsive in HomeKit, all appear as "Updating..."

[dotgrid]

HKKNX runs for a day or two without problems, then all my HKKNX devices become unresponsive and show as "updating" in the HomeKit UI.

• Sometimes after ~10 minutes the devices recover and are responsive again
• Other times I have to restart HKKNX for the devices to respond.

I have included the logs below from three sessions. Let me know if you need any more information to help debug.

HKKNX is running on a Mac Mini server (M1/Silicon). The IP interface is a 1home Bridge device, connected directly to the bus.

Thanks in advance for your help!

---

$ hkknx ./hkknx -db ./database
INFO 2021/11/27 22:32:07 main.go:79: version 2.1.0 (built at 2021-11-08T13:57:09Z+0100)
INFO 2021/11/27 22:32:07 main.go:220: webpage available at port 8080
INFO 2021/11/27 22:32:09 app.go:321: tunnel: connected to 192.168.1.59:3671 via 1.8.28
INFO 2021/11/27 22:32:11 ip_transport.go:184: Listening on port 58955
INFO 2021/11/28 20:36:55 writer.go:141: context canceled
INFO 2021/11/28 20:36:55 writer.go:141: context canceled
INFO 2021/11/28 20:37:00 writer.go:141: context canceled
INFO 2021/11/28 20:37:40 writer.go:141: context canceled
INFO 2021/11/28 20:37:40 writer.go:141: context canceled
INFO 2021/11/28 20:37:41 writer.go:141: context canceled
INFO 2021/11/28 20:37:41 writer.go:141: context canceled
INFO 2021/11/28 20:37:44 writer.go:141: context canceled
INFO 2021/11/28 20:37:45 writer.go:141: context canceled
INFO 2021/11/28 20:37:45 writer.go:141: context canceled
INFO 2021/11/28 20:37:47 writer.go:141: context canceled
INFO 2021/11/28 23:01:12 app.go:321: tunnel: connected to 192.168.1.59:3671 via 1.8.4
INFO 2021/11/28 23:01:14 io.go:22: read 1/6/254: group read: timeout
INFO 2021/11/28 23:01:14 ip_transport.go:184: Listening on port 62974
INFO 2021/11/28 23:03:33 main.go:213: shutting down...
INFO 2021/11/28 23:03:33 tunnel.go:77: disconnecting from gateway...
INFO 2021/11/28 23:03:35 main.go:193: app: stop
INFO 2021/11/28 23:03:35 main.go:226: good bye ;)

$ hkknx ./hkknx -db ./database
INFO 2021/11/28 23:45:19 main.go:79: version 2.1.0 (built at 2021-11-08T13:57:09Z+0100)
INFO 2021/11/28 23:45:19 main.go:220: webpage available at port 8080
INFO 2021/11/28 23:45:21 app.go:321: tunnel: connected to 192.168.1.59:3671 via 1.8.30
INFO 2021/11/28 23:45:24 io.go:22: read 1/6/254: group read: timeout
INFO 2021/11/28 23:45:24 ip_transport.go:184: Listening on port 54281
INFO 2021/11/28 23:47:36 io.go:22: read 1/6/254: group read: timeout
INFO 2021/11/28 23:47:36 ip_transport.go:184: Listening on port 54739
INFO 2021/11/28 23:48:03 io.go:22: read 1/6/254: group read: timeout
INFO 2021/11/28 23:48:03 ip_transport.go:184: Listening on port 54797
INFO 2021/11/28 23:48:07 io.go:22: read 1/6/254: group read: timeout
INFO 2021/11/28 23:48:07 ip_transport.go:184: Listening on port 54798
INFO 2021/11/28 23:48:21 io.go:22: read 1/6/254: group read: timeout
INFO 2021/11/28 23:48:21 ip_transport.go:184: Listening on port 54849
INFO 2021/11/28 23:48:30 io.go:22: read 1/6/254: group read: timeout
INFO 2021/11/28 23:48:30 ip_transport.go:184: Listening on port 54855
INFO 2021/11/28 23:50:28 io.go:22: read 1/6/254: group read: timeout
INFO 2021/11/28 23:50:28 ip_transport.go:184: Listening on port 55179
INFO 2021/11/28 23:52:10 io.go:22: read 2/0/43: group read: timeout
INFO 2021/11/28 23:52:10 io.go:22: read 2/0/44: group read: timeout
INFO 2021/11/28 23:52:12 io.go:22: read 1/6/254: group read: timeout
INFO 2021/11/28 23:52:12 ip_transport.go:184: Listening on port 55437
INFO 2021/11/28 23:52:29 io.go:22: read 1/6/254: group read: timeout
INFO 2021/11/28 23:52:29 ip_transport.go:184: Listening on port 55493
INFO 2021/11/28 23:52:43 io.go:22: read 2/0/43: group read: timeout
INFO 2021/11/28 23:52:44 io.go:22: read 2/0/44: group read: timeout
INFO 2021/11/28 23:52:46 io.go:22: read 1/6/254: group read: timeout
INFO 2021/11/28 23:52:46 ip_transport.go:184: Listening on port 55510
INFO 2021/11/28 23:54:26 io.go:22: read 2/0/43: group read: timeout
INFO 2021/11/28 23:54:27 io.go:22: read 2/0/44: group read: timeout
INFO 2021/11/28 23:54:28 ip_transport.go:184: Listening on port 55734
INFO 2021/11/28 23:55:13 io.go:22: read 2/0/43: group read: timeout
INFO 2021/11/28 23:55:13 io.go:22: read 2/0/44: group read: timeout
INFO 2021/11/28 23:55:15 ip_transport.go:184: Listening on port 55946
INFO 2021/11/28 23:55:40 io.go:22: read 2/0/43: group read: timeout
INFO 2021/11/28 23:55:40 io.go:22: read 2/0/44: group read: timeout
INFO 2021/11/28 23:55:42 ip_transport.go:184: Listening on port 56010
INFO 2021/11/28 23:55:43 io.go:22: read 2/0/43: group read: timeout
INFO 2021/11/28 23:55:44 io.go:22: read 2/0/44: group read: timeout
INFO 2021/11/28 23:55:45 ip_transport.go:184: Listening on port 56027
INFO 2021/11/28 23:55:47 io.go:22: read 2/0/43: group read: timeout
INFO 2021/11/28 23:55:48 io.go:22: read 2/0/44: group read: timeout
INFO 2021/11/28 23:55:49 ip_transport.go:184: Listening on port 56053
INFO 2021/11/28 23:56:11 io.go:22: read 2/0/43: group read: timeout
INFO 2021/11/28 23:56:11 io.go:22: read 2/0/44: group read: timeout
INFO 2021/11/28 23:56:13 ip_transport.go:184: Listening on port 56159
INFO 2021/11/28 23:57:42 io.go:22: read 2/0/43: group read: timeout
INFO 2021/11/28 23:57:42 io.go:22: read 2/0/44: group read: timeout
INFO 2021/11/28 23:57:44 ip_transport.go:184: Listening on port 56425
INFO 2021/11/28 23:58:20 io.go:22: read 2/0/43: group read: timeout
INFO 2021/11/28 23:58:21 io.go:22: read 2/0/44: group read: timeout
INFO 2021/11/28 23:58:22 ip_transport.go:184: Listening on port 56591
INFO 2021/11/28 23:58:50 io.go:22: read 2/0/43: group read: timeout
INFO 2021/11/28 23:58:50 io.go:22: read 2/0/44: group read: timeout
INFO 2021/11/28 23:58:52 ip_transport.go:184: Listening on port 56648
INFO 2021/11/28 23:59:24 main.go:213: shutting down...
INFO 2021/11/28 23:59:24 tunnel.go:77: disconnecting from gateway...
INFO 2021/11/28 23:59:26 main.go:193: app: stop
INFO 2021/11/28 23:59:26 main.go:226: good bye ;)

$ hkknx ./hkknx -db ./database
INFO 2021/11/28 23:59:44 main.go:79: version 2.1.0 (built at 2021-11-08T13:57:09Z+0100)
INFO 2021/11/28 23:59:44 main.go:220: webpage available at port 8080
INFO 2021/11/28 23:59:46 app.go:321: tunnel: connected to 192.168.1.59:3671 via 1.8.30
INFO 2021/11/28 23:59:47 io.go:22: read 2/0/43: group read: timeout
INFO 2021/11/28 23:59:48 io.go:22: read 2/0/44: group read: timeout
INFO 2021/11/28 23:59:50 ip_transport.go:184: Listening on port 56824
2021/11/29 13:15:08 heartbeat: write udp4 192.168.1.242:61543->192.168.1.59:3671: sendto: can't assign requested address
2021/11/29 13:15:08 reconnect: write udp4 192.168.1.242:61543->192.168.1.59:3671: sendto: can't assign requested address
INFO 2021/11/29 13:15:54 app.go:321: tunnel: connected to 192.168.1.59:3671 via 1.8.30
INFO 2021/11/29 13:15:55 io.go:22: read 2/0/43: group read: timeout
INFO 2021/11/29 13:15:55 io.go:22: read 2/0/44: group read: timeout
INFO 2021/11/29 13:15:57 io.go:22: read 1/5/50: group read: timeout
INFO 2021/11/29 13:15:58 ip_transport.go:184: Listening on port 52693
INFO 2021/11/29 22:27:48 io.go:22: read 2/0/43: group read: timeout
INFO 2021/11/29 22:27:48 io.go:22: read 2/0/44: group read: timeout
INFO 2021/11/29 22:27:51 io.go:22: read 1/5/50: group read: timeout
INFO 2021/11/29 22:27:51 ip_transport.go:184: Listening on port 49963
INFO 2021/11/29 22:27:58 io.go:22: read 2/0/43: group read: timeout
INFO 2021/11/29 22:27:58 io.go:22: read 2/0/44: group read: timeout
INFO 2021/11/29 22:28:00 io.go:22: read 1/5/50: group read: timeout
INFO 2021/11/29 22:28:00 ip_transport.go:184: Listening on port 50021
2021/11/30 00:39:17 log: failed to write msg: WebSocket closed: received close frame: status = StatusNoStatusRcvd and reason = ""
INFO 2021/11/30 22:08:37 writer.go:141: context canceled
INFO 2021/11/30 22:08:38 writer.go:141: context canceled
INFO 2021/11/30 22:08:44 writer.go:141: context canceled
INFO 2021/12/01 01:18:31 writer.go:141: context canceled
INFO 2021/12/01 01:18:34 writer.go:141: context canceled
INFO 2021/12/01 01:18:38 writer.go:141: context canceled
INFO 2021/12/01 01:18:39 writer.go:141: context canceled
INFO 2021/12/01 04:04:23 writer.go:141: context canceled
INFO 2021/12/01 04:04:24 writer.go:141: context canceled
INFO 2021/12/01 04:04:27 writer.go:141: context canceled
INFO 2021/12/01 04:04:27 writer.go:141: context canceled
INFO 2021/12/01 04:05:07 writer.go:141: context canceled
INFO 2021/12/01 04:05:07 writer.go:141: context canceled
INFO 2021/12/01 04:05:08 writer.go:141: context canceled
INFO 2021/12/01 04:05:12 writer.go:141: context canceled
INFO 2021/12/02 00:08:46 writer.go:141: context canceled
2021/12/03 05:28:05 heartbeat: connection not found
2021/12/03 05:28:05 reconnected
2021/12/04 14:13:11 discarding message with sequence number 6 (expected 7)
INFO 2021/12/04 23:41:16 writer.go:141: context canceled
INFO 2021/12/04 23:41:16 writer.go:141: context canceled
INFO 2021/12/04 23:41:17 writer.go:141: context canceled

[dotgrid]

In case this is helpful, the 1home Bridge supports:

Up to 8 KNXnet/IP Tunneling connections simultaneously

I am not certain, but HKKNX seems to move on to a new connection/tunnel each time—could it be exhausting all eight connections?

[brutella]

Please include the flag --verbose when running hkknx to also see the DEBUG log messages. Those might include helpful information about your issue.

[gisbertpeter]

I observed the same behavior of the unresponsitivity in HomeKit after x days of correct operation. HKKNX runs on a Raspberry PI4, LINUX homebridge 5.10.17

[hr-automation]

Ich kann die oben beschriebenen Verbindungsunterbrüche ebenfalls bestätigen.

OS: Offizielles 1.3.x Raspberry Image von HKKNX - aktualisiert auf 2.1.1

Anbei ein paar Zeilen meines LOG-Files:

2021-12-06_12:45:19.29915 INFO 2021/12/06 13:45:19 io.go:22: read 1/2/199: group read: timeout 2021-12-06_12:45:19.94334 INFO 2021/12/06 13:45:19 io.go:22: read 1/2/23: group read: timeout 2021-12-06_12:45:20.54536 INFO 2021/12/06 13:45:20 io.go:22: read 1/2/53: group read: timeout 2021-12-06_12:45:20.59660 INFO 2021/12/06 13:45:20 ip_transport.go:184: Listening on port 33573 2021-12-06_21:51:44.70349 2021/12/06 22:51:44 discarding message with sequence number 133 (expected 134) 2021-12-07_01:50:33.86634 2021/12/07 02:50:33 discarding message with sequence number 78 (expected 79) 2021-12-07_07:50:42.45548 2021/12/07 08:50:42 discarding message with sequence number 138 (expected 139) 2021-12-08_03:33:57.36944 2021/12/08 04:33:57 discarding message with sequence number 85 (expected 86) 2021-12-08_11:35:16.29226 2021/12/08 12:35:16 discarding message with sequence number 3 (expected 4) 2021-12-08_14:36:51.68751 2021/12/08 15:36:51 discarding message with sequence number 210 (expected 211)

Als Abhilfe, habe ich mir einen Cronjob am Raspberry PI eingerichtet - welcher in der Nacht den Raspberry neu startet.

Falls @brutella keine Lösung findet - hier ein temporärer Lösungsansatz:

sudo crontab -e und folgenden Eintrag hinzufügen: 0 4 * * * /sbin/shutdown -r now

EDIT: Das Problem dürfte nicht nur in Verbindung mit der offiziellen HomeKit App von Apple auftreten, sondern auch mit der Home+ App von @brutella

LG

[brutella]

As mention in this post (in German), disabling iCloud Private Relay might resolve this issue.

[hr-automation]

@brutella This doesn´t help! I have already deactivated iCloud Privat Relay in the past.

[dotgrid]

--verbose

Here's the verbose output! Does this help to find the problem?

hkknx ./hkknx -db ./database --verbose
INFO 2021/12/09 17:53:10 main.go:79: version 2.1.0 (built at 2021-11-08T13:57:09Z+0100)
INFO 2021/12/09 17:53:10 main.go:220: webpage available at port 8080
INFO 2021/12/09 17:53:13 app.go:321: tunnel: connected to 192.168.1.59:3671 via 1.8.30
DEBUG 2021/12/09 17:53:13 app.go:402: ntp: disabled
DEBUG 2021/12/09 17:53:13 io.go:15: read: 1/2/3
DEBUG 2021/12/09 17:53:13 io.go:15: read: 1/2/4
DEBUG 2021/12/09 17:53:13 io.go:15: read: 2/0/8
DEBUG 2021/12/09 17:53:13 io.go:15: read: 2/0/9
DEBUG 2021/12/09 17:53:13 io.go:15: read: 2/0/13
DEBUG 2021/12/09 17:53:13 io.go:15: read: 2/0/14
DEBUG 2021/12/09 17:53:13 io.go:15: read: 1/0/8
DEBUG 2021/12/09 17:53:13 io.go:15: read: 1/0/9
DEBUG 2021/12/09 17:53:13 io.go:15: read: 2/0/23
DEBUG 2021/12/09 17:53:13 io.go:15: read: 2/0/24
DEBUG 2021/12/09 17:53:13 io.go:15: read: 2/0/28
DEBUG 2021/12/09 17:53:13 io.go:15: read: 2/0/29
DEBUG 2021/12/09 17:53:13 io.go:15: read: 2/0/43
INFO 2021/12/09 17:53:14 io.go:22: read 2/0/43: group read: timeout
DEBUG 2021/12/09 17:53:14 io.go:15: read: 2/0/44
INFO 2021/12/09 17:53:14 io.go:22: read 2/0/44: group read: timeout
DEBUG 2021/12/09 17:53:14 io.go:15: read: 1/0/13
DEBUG 2021/12/09 17:53:14 io.go:15: read: 1/0/14
DEBUG 2021/12/09 17:53:14 io.go:15: read: 1/1/3
DEBUG 2021/12/09 17:53:14 io.go:15: read: 1/1/4
DEBUG 2021/12/09 17:53:14 io.go:15: read: 1/2/8
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/2/13
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/3/3
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/3/13
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/3/14
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/4/3
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/4/4
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/5/3
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/5/4
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/5/8
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/5/9
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/5/28
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/5/29
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/5/33
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/5/34
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/6/3
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/6/4
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/6/8
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/6/9
DEBUG 2021/12/09 17:53:15 io.go:15: read: 1/6/13
DEBUG 2021/12/09 17:53:16 io.go:15: read: 1/6/14
DEBUG 2021/12/09 17:53:16 io.go:15: read: 1/6/18
DEBUG 2021/12/09 17:53:16 io.go:15: read: 1/6/19
DEBUG 2021/12/09 17:53:16 io.go:15: read: 1/7/8
DEBUG 2021/12/09 17:53:16 io.go:15: read: 1/7/9
DEBUG 2021/12/09 17:53:16 io.go:15: read: 1/7/13
DEBUG 2021/12/09 17:53:16 io.go:15: read: 1/7/14
DEBUG 2021/12/09 17:53:16 io.go:15: read: 1/6/50
DEBUG 2021/12/09 17:53:16 io.go:15: read: 2/0/50
DEBUG 2021/12/09 17:53:16 io.go:15: read: 1/5/50
DEBUG 2021/12/09 17:53:16 io.go:15: read: 1/0/50
DEBUG 2021/12/09 17:53:16 io.go:15: read: 3/0/3
DEBUG 2021/12/09 17:53:16 io.go:15: read: 3/0/8
DEBUG 2021/12/09 17:53:16 io.go:15: read: 3/0/13
INFO 2021/12/09 17:53:16 ip_transport.go:184: Listening on port 52377
DEBUG 2021/12/09 17:53:18 pair-verify.go:37: 192.168.1.40:51158 POST /pair-verify
DEBUG 2021/12/09 17:53:18 pair-verify.go:44: Create new pair verify controller
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:93: ->     A: 7f19f4b4fd226234dfe862f284b24b358a892da78388e0bc121cc9e179389d14
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:127:        K: ade19dbcd63ea2609c881f04945878ab5ed360f787f6ad428b3da33878ebf6a6
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:128:        B: 8fa292515e87770fba799d807d2093d81ee7b221d2f17196d3714191e2844276
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:129:        S: 7c17b22aa32660a94bf2083d8b1931b740f2b8071b980401d615f77ad5d12ba7
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:130:   Shared: 3acc47c95fea349f39e757cff237f3bc3faf10f205bbd947a9a221ffad684f6b
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:132: <-     B: 8fa292515e87770fba799d807d2093d81ee7b221d2f17196d3714191e2844276
DEBUG 2021/12/09 17:53:18 pair-verify.go:37: 192.168.1.40:51158 POST /pair-verify
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:152: ->     Message: c0bd0075c08b9d42c94c33226634f54b52c8967d49d73f945d795e5cfab200e661733149e5cbfdeb10e5a9a5c4f1afb0e54f42574fc553f2198074ee89159a8945fdefbb23c847504e4efbee6d022b3f19144dc2bf40abc90bb38417d1f7b0ed2f14d9c5fe32288e
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:153: ->     MAC: d4b6da2193ea0a8cad28e896bd381dc7
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:172:     client: 7FFB5D3C-FA0D-44DA-882D-BC7657920054
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:173:  signature: 7e84602c5248b875dabf1f407d1a4385022b81e672406e8af8cfe8c53ce7abb16388dae565e69cdc72ec5aff1ee262a905920130a60e537fa30e47edf737740c
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:194: signature is valid
DEBUG 2021/12/09 17:53:18 pair-verify.go:70: Setup secure session
DEBUG 2021/12/09 17:53:18 accessories.go:13: 192.168.1.40:51158 GET /accessories
DEBUG 2021/12/09 17:53:18 pair-verify.go:37: 192.168.1.74:58407 POST /pair-verify
DEBUG 2021/12/09 17:53:18 pair-verify.go:44: Create new pair verify controller
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:93: ->     A: f53f7c9249336c7e91dcd612b5bba5dede3d865b2d83088e742c370a2fc81c07
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:127:        K: 9eb5a2eb47ad30c66560f8aaeeb81d7afe1392980c4e480291764da214663286
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:128:        B: 7932295f3dc6e44c145ee4d69d4b3faec408bcc0114d22d60e0cb9b3cc964d58
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:129:        S: b73cb8b5aa54aa10996715cdf48d3ac573b34e482144b68b0a1501ab230091d1
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:130:   Shared: 105a82235bf6ed48d88f928f13e6c392449c33e0d0d61149e5feab75cd0a4e25
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:132: <-     B: 7932295f3dc6e44c145ee4d69d4b3faec408bcc0114d22d60e0cb9b3cc964d58
DEBUG 2021/12/09 17:53:18 pair-verify.go:37: 192.168.1.74:58407 POST /pair-verify
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:152: ->     Message: 67696dc5a16106bddc659d40d476d8bff68d8dbf2b584f5e9684686ba31a00b852c9827199fbe603fb2699133b83086f87ffaaff4a8b9b29c28a6ad0a8e045872483bef4be8e8cc34f2e013c84618aee9ac0ec44e609e2632fe4d9bf3ccd3c117272523e87679bf7
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:153: ->     MAC: 7b5370572275a4b8aeea347518c09d5d
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:172:     client: 7FFB5D3C-FA0D-44DA-882D-BC7657920054
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:173:  signature: d1de0d27b097106cdd0a46c082e54b8aa3190ecbab5360c056f998c8137d6fdfa893f59d66e73f639d10dfe8c22c6ad9ed1a9f2888cde140f63997dc5fbf4208
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:194: signature is valid
DEBUG 2021/12/09 17:53:18 pair-verify.go:70: Setup secure session
DEBUG 2021/12/09 17:53:18 accessories.go:13: 192.168.1.74:58407 GET /accessories
DEBUG 2021/12/09 17:53:18 pair-verify.go:37: 192.168.1.99:51890 POST /pair-verify
DEBUG 2021/12/09 17:53:18 pair-verify.go:44: Create new pair verify controller
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:93: ->     A: 47d83ec1e160333db37ce4867d89d3b992009b5e58006ac073fe4d05f99b572a
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:127:        K: 179a6346bd0d6f715eb0b95290dc1beed42f12fc928f210dfc4d0247b11fe5f9
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:128:        B: b8afd8b98c12e99df95294661ed9fa3a76441efa9f5f2b16460300697af0b639
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:129:        S: 6521f5cb6c1fe4523e7941a67677655112dcfccea421961aec954c85f0ec4dd0
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:130:   Shared: 6977400efeddb3ef9d255570096feefa744e276cff1dafc1086fc452b6bbec60
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:132: <-     B: b8afd8b98c12e99df95294661ed9fa3a76441efa9f5f2b16460300697af0b639
DEBUG 2021/12/09 17:53:18 pair-verify.go:37: 192.168.1.99:51890 POST /pair-verify
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:152: ->     Message: fb631da87f47c1160a5290d3f9f009d9b34b55ace65f990374ac38d20b0a0cf0192aa1c9ae6d9ba32bd291d5183cf5338a9384d462180ded8459b96eab4d594225194a0be46918bb7f9fe91e5b1fc794dfdfecb97fa5af71b9a117e3c53ffb539e795c1202e57df0
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:153: ->     MAC: 0870d67ea65b9fd88713933a072bd141
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:172:     client: 7FFB5D3C-FA0D-44DA-882D-BC7657920054
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:173:  signature: 7b75de8a437226874930e9a0494ae236580c313c60f735decdd74fce6ecff86c7c651df70f88890b1d0e12d0f88a329c8202f32ad65c753f5e0023a735170404
DEBUG 2021/12/09 17:53:18 verify_server_controller.go:194: signature is valid
DEBUG 2021/12/09 17:53:18 pair-verify.go:70: Setup secure session
DEBUG 2021/12/09 17:53:18 accessories.go:13: 192.168.1.99:51890 GET /accessories
DEBUG 2021/12/09 17:53:19 characteristics.go:102: 192.168.1.74:58407 PUT /characteristics
DEBUG 2021/12/09 17:53:19 characteristics.go:107: {"characteristics":[{"aid":36,"iid":10,"ev":true}]}
DEBUG 2021/12/09 17:53:19 characteristics.go:102: 192.168.1.74:58407 PUT /characteristics
DEBUG 2021/12/09 17:53:19 characteristics.go:107: {"characteristics":[{"aid":29,"iid":10,"ev":true},{"aid":29,"iid":11,"ev":true}]}
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[18.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:102: 192.168.1.74:58407 PUT /characteristics
DEBUG 2021/12/09 17:53:19 characteristics.go:107: {"characteristics":[{"aid":32,"iid":10,"ev":true}]}
DEBUG 2021/12/09 17:53:19 characteristics.go:102: 192.168.1.74:58407 PUT /characteristics
DEBUG 2021/12/09 17:53:19 characteristics.go:107: {"characteristics":[{"aid":19,"iid":10,"ev":true},{"aid":19,"iid":11,"ev":true}]}
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[39.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[37.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[41.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[26.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[3.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[13.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[17.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[2.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[28.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[25.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[11.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[20.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[36.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[4.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[21.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[14.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[10.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[7.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[6.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[8.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[23.7]]
DEBUG 2021/12/09 17:53:19 pair-verify.go:37: 192.168.1.15:53274 POST /pair-verify
DEBUG 2021/12/09 17:53:19 pair-verify.go:44: Create new pair verify controller
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:93: ->     A: aa23fd6b66333fe309ea9b7274a70ea855dd4a76d4b245c29af5b88808e6240c
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[29.7]]
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:127:        K: a726da949b43af95fa1f22fe2d1851c84155df56fed9b062123d9b7b3e7e98f4
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:128:        B: 1f765de682775031fc9dc6ab7385478db0697862a93882612fbd649b683f9d13
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:129:        S: 6c353d64b36b111c52a08cd71124bd2238b70a82646a314b556cca0b780206c4
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:130:   Shared: e99dff2807b2096c0396535160297e0c314137e14d058ed3c723f5c1264ecd2f
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:132: <-     B: 1f765de682775031fc9dc6ab7385478db0697862a93882612fbd649b683f9d13
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[38.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[15.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[12.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[32.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[22.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[19.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[40.7]]
DEBUG 2021/12/09 17:53:19 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[24.7]]
DEBUG 2021/12/09 17:53:19 pair-verify.go:37: 192.168.1.15:53274 POST /pair-verify
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:152: ->     Message: 1678f099645add262c9a2c66790a19b742772e727625e3546a588dfc06782ec3df26fe5389a049634ed4c21d719b8329f63af9a5fd207975f627b252b58dba62f4326cebd70280c543380f671a17c897af90ddc7e0f6d8de6d2551dd65ce313ac6eeb9a7ece98b8a
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:153: ->     MAC: 331a7f167518e13c752ed255cb0852d5
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:172:     client: 7FFB5D3C-FA0D-44DA-882D-BC7657920054
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:173:  signature: b30e57177757454a428b4b92dd9a1dca862dc08fc4eec679dd2e950c8dbd65aaa94cf8820f52a0a7bfb61ccc70c74cbfaa7acecdfff086af7fe1dd673df3b301
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:194: signature is valid
DEBUG 2021/12/09 17:53:19 pair-verify.go:70: Setup secure session
DEBUG 2021/12/09 17:53:19 accessories.go:13: 192.168.1.15:53274 GET /accessories
DEBUG 2021/12/09 17:53:19 pair-verify.go:37: 192.168.1.25:54759 POST /pair-verify
DEBUG 2021/12/09 17:53:19 pair-verify.go:44: Create new pair verify controller
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:93: ->     A: 7facba5cf5b9b728edebea6be956e505e53eb9b7af8adf821516a294799a4018
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:127:        K: e121b56aafb003df1d3007f2d88f32b7af23be7acfd107a45b75d761c42d8e66
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:128:        B: 965766033eda8a665503baef78a4549ccedc4bd0018d32c67d5bc0a2b4cfdc4d
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:129:        S: f67f7d9546e2b1ba6ca9de35e5e306303051656ae4b63a9b5dcfa7fe97764c6d
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:130:   Shared: 148d2ca670b59cdca57b8f726c4b246c5e5b8c1615c22087edab93a99f34716b
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:132: <-     B: 965766033eda8a665503baef78a4549ccedc4bd0018d32c67d5bc0a2b4cfdc4d
DEBUG 2021/12/09 17:53:19 pair-verify.go:37: 192.168.1.25:54759 POST /pair-verify
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:152: ->     Message: 74214dcee6296017b751b92a3141d1cedf57299a5700017a8e11669b4d092bcb84125db1e8147bcec831756882d45b4e4fd4912b5ba6741adc2d6298174a2e677ebb70a7fa641f0b959b935491f0da4a46887d481bba5e441cbd55235000b9558b3da3a0d4e31c28
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:153: ->     MAC: 7f394483ce2d4ff3c140c9e9181f982a
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:172:     client: 7FFB5D3C-FA0D-44DA-882D-BC7657920054
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:173:  signature: 17114a30306c326fc54aa16e6790f8bf027c7a27ae65ac18b2adfbb9211b9119bbec6c7cc12997058ea619908e10ccf82c5417f5e6f77ad9d1e6fbedb6e37000
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:194: signature is valid
DEBUG 2021/12/09 17:53:19 pair-verify.go:70: Setup secure session
DEBUG 2021/12/09 17:53:19 accessories.go:13: 192.168.1.25:54759 GET /accessories
DEBUG 2021/12/09 17:53:19 pair-verify.go:37: 192.168.1.128:53220 POST /pair-verify
DEBUG 2021/12/09 17:53:19 pair-verify.go:44: Create new pair verify controller
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:93: ->     A: a1733a222fd6b7c21308336f9c21734aadfb1ccb0d51d93ec524fa9d11282775
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:127:        K: 3fecc46a23d3c6cacc90f028b636ba2936679c08939f812b6157605c0e846a70
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:128:        B: f5e5a5d462bfdf59f4a0c0589faf5a9f30ee39d691bb55c5437720641edc0f64
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:129:        S: 808c4cf72c719e5845d9dd3863206a56bea497346f08422428b0e95edc5a538e
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:130:   Shared: eb57892317b9764d9dc6214506a4ed70bbd82c389b50fe39021e8a8104a9d83f
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:132: <-     B: f5e5a5d462bfdf59f4a0c0589faf5a9f30ee39d691bb55c5437720641edc0f64
DEBUG 2021/12/09 17:53:19 pair-verify.go:37: 192.168.1.79:53517 POST /pair-verify
DEBUG 2021/12/09 17:53:19 pair-verify.go:44: Create new pair verify controller
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:93: ->     A: b5a83626b12715317914035d9b0623a6ef5e54b26c37e6b3a3492a478b99cb4b
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:127:        K: df1c8c57252d202a397fb32d2718f2c8b0a6672eb9219d2d3edf7155128b4453
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:128:        B: a9505c4752ce605ad5908d3aa01b6abef2f939435fce0cb926bad91d9693e839
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:129:        S: 4aa1c0c6c269f69f82ac264a26a22b14cdaa2d7ec096d43eda4ec3584d0c1ceb
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:130:   Shared: 9abbd9e91ac13d38b2de18383764df371a6c858d3870b0f88ea8bf2538cf7a70
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:132: <-     B: a9505c4752ce605ad5908d3aa01b6abef2f939435fce0cb926bad91d9693e839
DEBUG 2021/12/09 17:53:19 pair-verify.go:37: 192.168.1.128:53220 POST /pair-verify
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:152: ->     Message: 3b07fcf661808710a83c8837f5436bc76ec412405d06832959f8ea168148df2654b4dd692248f9715cc364d0523b59350d7735de7f02ae753237d497c4646a11ab74342da9f9d4f77603ffdc0933a19e54fe9a69778fbae594f74011c56e414ae88fc5de66002685
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:153: ->     MAC: ddd610744cb581f7e454a9ef1119db76
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:172:     client: 7FFB5D3C-FA0D-44DA-882D-BC7657920054
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:173:  signature: 4446961bcbb5f6e7b936e10bfd358ec6e60d0626fc2421730be4b2cb172155ecafa0162b26200a0e99d297413f17ca16ad358063efd68aa2b202b80ce7967806
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:194: signature is valid
DEBUG 2021/12/09 17:53:19 pair-verify.go:70: Setup secure session
DEBUG 2021/12/09 17:53:19 accessories.go:13: 192.168.1.128:53220 GET /accessories
DEBUG 2021/12/09 17:53:19 pair-verify.go:37: 192.168.1.154:49746 POST /pair-verify
DEBUG 2021/12/09 17:53:19 pair-verify.go:44: Create new pair verify controller
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:93: ->     A: 853388535e77a7b7ceda77f0253ac214f18f5de5b6130519053f56672634d37e
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:127:        K: a6ccca7ff151eb075647da9de012c817b23f51d6f4810c9824ae48f5fc9069b6
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:128:        B: 43024b29eafb306f1283d01727a9703914f7c36a48ad99d92d59fd419dd52044
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:129:        S: 90c6082bcfbc4b1f071a38007fb5654a5bcbf8196ceca01e65ca77f18c92ccfc
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:130:   Shared: c39f1a6fb9bb8ea5a31555e7aef2eb863866df35c14ec4f10411b9706d19bd1f
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:132: <-     B: 43024b29eafb306f1283d01727a9703914f7c36a48ad99d92d59fd419dd52044
DEBUG 2021/12/09 17:53:19 pair-verify.go:37: 192.168.1.79:53517 POST /pair-verify
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:152: ->     Message: 4644ec288e022dbf4318496e903410540c1fe80ac3db04c41998bacfdf72e80390ad2b781405d902a0fff8edc667c23812a8335fb668fd49e7d6c7dafbb9d99bf5f792926f5b7a4d847dcef01f361cdfe7174b875745f146978763d3f89360cf1eadde3d686c4f53
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:153: ->     MAC: 985f08b0b3f4303505b25eef507cb68f
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:172:     client: 7FFB5D3C-FA0D-44DA-882D-BC7657920054
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:173:  signature: 0a5053771dd0cbb5c2ad329546fa164074232b3594232407b10d47cddb0775702f57ea788353213bc91156102664f653994cb6c1127d0e881bdb93a384456e07
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:194: signature is valid
DEBUG 2021/12/09 17:53:19 pair-verify.go:70: Setup secure session
DEBUG 2021/12/09 17:53:19 characteristics.go:102: 192.168.1.15:53274 PUT /characteristics
DEBUG 2021/12/09 17:53:19 characteristics.go:107: {"characteristics":[{"aid":19,"iid":10,"ev":true},{"aid":19,"iid":11,"ev":true}]}
DEBUG 2021/12/09 17:53:19 accessories.go:13: 192.168.1.79:53517 GET /accessories
DEBUG 2021/12/09 17:53:19 pair-verify.go:37: 192.168.1.154:49746 POST /pair-verify
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:152: ->     Message: dbd0df4e4bcc26f95fc9f5b157dbbd61ba699a52c586e91af71545e00e992a0c469994c5bbe3770b5bb5336a3da2f6b72e2b57d67ee97eec86ebff9903d98d815c65fef2636d968b02057a0eb4673dd603556bbbdee9655fb4bf5d8788acde06004e1580eb6a721e
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:153: ->     MAC: 9f9805179a185577c8e038d14fe9aab8
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:172:     client: 7FFB5D3C-FA0D-44DA-882D-BC7657920054
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:173:  signature: f9a1733c014bf73a1f295dbc66b55716d10e88782a9a4d19b3d67f77fff0285b2c49155381923658bffb0e11f8b0fcf65ff90a94f0f84b5253ac7beb4d43b00a
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:194: signature is valid
DEBUG 2021/12/09 17:53:19 pair-verify.go:70: Setup secure session
DEBUG 2021/12/09 17:53:19 accessories.go:13: 192.168.1.154:49746 GET /accessories
DEBUG 2021/12/09 17:53:19 characteristics.go:102: 192.168.1.15:53274 PUT /characteristics
DEBUG 2021/12/09 17:53:19 characteristics.go:107: {"characteristics":[{"aid":29,"iid":10,"ev":true},{"aid":29,"iid":11,"ev":true}]}
DEBUG 2021/12/09 17:53:19 characteristics.go:102: 192.168.1.79:53517 PUT /characteristics
DEBUG 2021/12/09 17:53:19 characteristics.go:107: {"characteristics":[{"aid":29,"iid":10,"ev":true},{"aid":29,"iid":11,"ev":true}]}
DEBUG 2021/12/09 17:53:19 characteristics.go:102: 192.168.1.79:53517 PUT /characteristics
DEBUG 2021/12/09 17:53:19 characteristics.go:107: {"characteristics":[{"aid":19,"iid":10,"ev":true},{"aid":19,"iid":11,"ev":true}]}
DEBUG 2021/12/09 17:53:19 characteristics.go:102: 192.168.1.128:53220 PUT /characteristics
DEBUG 2021/12/09 17:53:19 characteristics.go:107: {"characteristics":[{"aid":36,"iid":10,"ev":true}]}
DEBUG 2021/12/09 17:53:19 characteristics.go:102: 192.168.1.79:53517 PUT /characteristics
DEBUG 2021/12/09 17:53:19 characteristics.go:107: {"characteristics":[{"aid":32,"iid":10,"ev":true}]}
DEBUG 2021/12/09 17:53:19 pair-verify.go:37: [fe80::1010:ba91:10a4:8956%en0]:54138 POST /pair-verify
DEBUG 2021/12/09 17:53:19 pair-verify.go:44: Create new pair verify controller
DEBUG 2021/12/09 17:53:19 connection.go:112: Close connection and remove session
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:93: ->     A: c14ce689c3ebc8499a0f5521dcfec33731efd74d520873977d1d5b3fc48cb525
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:127:        K: edf515ba64ef2820fd214fc68dce54488e1a75aa2739c85efc627ac44b745bcc
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:128:        B: 3832499f2915ecd8f99e876d3b2e5c5a378d963f003903b637fe219a1f997605
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:129:        S: 119a0688cfd854f0f5a7be55df9b7207ad0e56c54bbd5260660c60a689e86fd1
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:130:   Shared: f344eb71a9bd7ec9d6beed5eccbf7605ec72dba19dc350360e16e536f16c0562
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:132: <-     B: 3832499f2915ecd8f99e876d3b2e5c5a378d963f003903b637fe219a1f997605
DEBUG 2021/12/09 17:53:19 pair-verify.go:37: [fe80::1010:ba91:10a4:8956%en0]:54138 POST /pair-verify
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:152: ->     Message: 93013941711380c3d4dcb179e87caffce4a4b3ed6b9baa007053f871b392b8f93d1a476649995b2e85d95de46104744251b87567f4b234e128b39caf13701bcf4650c19414c4c9ff58b7c919c290d5e7a53ba35ce5afdec4ee96fc0f29b97aae1757bd88cd460768
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:153: ->     MAC: 3bd83dffc97fff8dbb4b090e6eb07ce7
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:172:     client: 7FFB5D3C-FA0D-44DA-882D-BC7657920054
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:173:  signature: 74462b500752b0ef69815c78bce582a42f4de05090ecf81581fc0414037015ec991aedd10048857176df1f76e7d9258879de5ef862fbe55b4acc98d05e9d3004
DEBUG 2021/12/09 17:53:19 verify_server_controller.go:194: signature is valid
DEBUG 2021/12/09 17:53:19 pair-verify.go:70: Setup secure session
DEBUG 2021/12/09 17:53:19 accessories.go:13: [fe80::1010:ba91:10a4:8956%en0]:54138 GET /accessories
DEBUG 2021/12/09 17:53:19 characteristics.go:102: [fe80::1010:ba91:10a4:8956%en0]:54138 PUT /characteristics
DEBUG 2021/12/09 17:53:19 characteristics.go:107: {"characteristics":[{"aid":19,"iid":10,"ev":true},{"aid":19,"iid":11,"ev":true}]}
DEBUG 2021/12/09 17:53:19 characteristics.go:102: [fe80::1010:ba91:10a4:8956%en0]:54138 PUT /characteristics
DEBUG 2021/12/09 17:53:19 characteristics.go:107: {"characteristics":[{"aid":32,"iid":10,"ev":true}]}
DEBUG 2021/12/09 17:53:19 characteristics.go:102: [fe80::1010:ba91:10a4:8956%en0]:54138 PUT /characteristics
DEBUG 2021/12/09 17:53:19 characteristics.go:107: {"characteristics":[{"aid":29,"iid":10,"ev":true},{"aid":29,"iid":11,"ev":true}]}
DEBUG 2021/12/09 17:53:20 pair-verify.go:37: 192.168.1.48:58429 POST /pair-verify
DEBUG 2021/12/09 17:53:20 pair-verify.go:44: Create new pair verify controller
DEBUG 2021/12/09 17:53:20 verify_server_controller.go:93: ->     A: 92f1239ab9fb0ee37a90e12f44bc54f4a333e9011520c999070eb7ee083ccc43
DEBUG 2021/12/09 17:53:20 verify_server_controller.go:127:        K: 7e68684534388b40ab66ee838892b407e14f043c225a2ceb39732463bbf7e2f3
DEBUG 2021/12/09 17:53:20 verify_server_controller.go:128:        B: 6ed95e3a706d782ec2266ea595e53eab825342d294759c1bc1822d814ecd4178
DEBUG 2021/12/09 17:53:20 verify_server_controller.go:129:        S: 214b9ae361522fa2a1bbf21a3e944a7327a1da1bce4a7f03e457d6858936b7ff
DEBUG 2021/12/09 17:53:20 verify_server_controller.go:130:   Shared: d4e24a4d8567c4aa217a0f5baa47742721d4aa53bd97ff7f6649e061ebcc4b0b
DEBUG 2021/12/09 17:53:20 verify_server_controller.go:132: <-     B: 6ed95e3a706d782ec2266ea595e53eab825342d294759c1bc1822d814ecd4178
DEBUG 2021/12/09 17:53:20 pair-verify.go:37: 192.168.1.48:58429 POST /pair-verify
DEBUG 2021/12/09 17:53:20 verify_server_controller.go:152: ->     Message: 6971731d3db697f6f548f8e61ab8b489b185676ced8f967db0f83c4c347f5dc289dfaa8833b3b5aabdb1d239ef40ee9c89d08d114809dc4d6fc647f00e3f65cbcb25a20865bf269bcd8488498493023463e128ab9a947406200ab9e50870de65a58a6b45e3c30dfc
DEBUG 2021/12/09 17:53:20 verify_server_controller.go:153: ->     MAC: da2c29a3c5b0e3d51e99ec1c52cd3709
DEBUG 2021/12/09 17:53:20 verify_server_controller.go:172:     client: 7FFB5D3C-FA0D-44DA-882D-BC7657920054
DEBUG 2021/12/09 17:53:20 verify_server_controller.go:173:  signature: c8776f350b4519927b6f5f9afd338017eac61051161067f6481cb0a2777b9d4d5260b6a673a93215711873b494678635e83454594908b454e66bda1214285606
DEBUG 2021/12/09 17:53:20 verify_server_controller.go:194: signature is valid
DEBUG 2021/12/09 17:53:20 pair-verify.go:70: Setup secure session
DEBUG 2021/12/09 17:53:20 accessories.go:13: 192.168.1.48:58429 GET /accessories
DEBUG 2021/12/09 17:53:53 characteristics.go:59: 192.168.1.74:58407 GET /characteristics map[id:[29.11,29.10]]
DEBUG 2021/12/09 17:53:53 characteristics.go:102: 192.168.1.74:58407 PUT /characteristics
DEBUG 2021/12/09 17:53:53 characteristics.go:107: {"characteristics":[{"aid":29,"iid":11,"value":27},{"aid":29,"iid":10,"value":1}]}

[gisbertpeter]

I also had deactivated iCloud Privat Relay.

[hr-automation]

@paulfarnell & @gisbertpeter More than one Homepod Mini as Control Center?

[gisbertpeter]

I have a „2021 Apple TV 4K (32GB)“

[gisbertpeter]

One additional remark. In parallel I have a Zigbee stick connected via Raspberry PI and Homebridge. The Zigbee devices are not disconnect only the HKKNX devices.

[dotgrid]

@paulfarnell & @gisbertpeter More than one Homepod Mini as Control Center?

I have several HomePods and several Apple TVs in the house. Is that a problem here?

[hr-automation]

@paulfarnell & @gisbertpeter More than one Homepod Mini as Control Center?

I have several HomePods and several Apple TVs in the house. Is that a problem here?

I have seen several local IP Adresses on your Log-Files. And i know, HomePods (mini) can be a possible Problem (seen that in several issues here!). Apple TVs are not the problem what i can reconstruct at this moment.

@brutella should be more concentrated on this topic - It looks like, there are much problems! iCloud Private Replay is not the main problem in my opinion!

[brutella]

@paulfarnell I can't find any log files which indicate a connection issue. Do you have any other HomeKit services running on your computer, for example a Homebridge plugin?

[brutella]

@gisbertpeter The last log message looks suspicious. I've never seen a request for negative id values. Do you know what device on your network has the IP address 192.168.0.53?

[dotgrid]

@paulfarnell I can't find any log files which indicate a connection issue. Do you have any other HomeKit services running on your computer, for example a Homebridge plugin?

@brutella Thanks for looking into this.

I am running Homebridge on that Mac Mini, with a plugin for my Samsung TV. Should I disable the plugin? Or disable Homebridge entirely?

Is there a Homebridge log I could provide that would help uncover the issue?

[dotgrid]

@brutella I was able to capture more of the debug log. Crucially, this log covers a period when all my hnknx devices became unavailable.

The full log is saved as a gist, since it's quite large.

Lines 342–363 are possibly the most interesting.

[dotgrid]

@paulfarnell I can't find any log files which indicate a connection issue. Do you have any other HomeKit services running on your computer, for example a Homebridge plugin?

@brutella Here's something new. When I restart Homebridge (running on the same machine as hkknx) I see the following in the hkknx logs. This is reproducible every time Homebridge restarts.

2021/12/10 17:05:54 "GET http:/// HTTP/1.0" from 192.168.1.1:59344 - 303 73B in 334.833µs
2021/12/10 17:05:54 "OPTIONS http:/// HTTP/1.0" from 192.168.1.1:59478 - 405 0B in 78.584µs
2021/12/10 17:05:54 "GET http:///nice%20ports%2C/Tri%6Eity.txt%2ebak HTTP/1.0" from 192.168.1.1:59490 - 404 19B in 69µs
DEBUG 2021/12/10 17:05:56 accessories.go:13: 192.168.1.242:65135 GET /accessories
DEBUG 2021/12/10 17:05:56 connection.go:112: Close connection and remove session
DEBUG 2021/12/10 17:05:56 characteristics.go:102: 192.168.1.242:65136 PUT /characteristics
DEBUG 2021/12/10 17:05:56 characteristics.go:107: {"characteristics":[{"aid":-1,"iid":-1}]}
DEBUG 2021/12/10 17:05:56 characteristics.go:115: json: cannot unmarshal number -1 into Go struct field CharacteristicRequest.characteristics.aid of type uint64
DEBUG 2021/12/10 17:05:56 connection.go:112: Close connection and remove session
DEBUG 2021/12/10 17:06:34 characteristics.go:59: 192.168.1.40:51444 GET /characteristics map[id:[13.7]]
DEBUG 2021/12/10 17:06:34 characteristics.go:59: 192.168.1.40:51444 GET /characteristics map[id:[29.7]]
DEBUG 2021/12/10 17:06:34 characteristics.go:59: 192.168.1.40:51444 GET /characteristics map[id:[3.7]]
DEBUG 2021/12/10 17:06:34 characteristics.go:59: 192.168.1.40:51444 GET /characteristics map[id:[10.7]]
DEBUG 2021/12/10 17:06:34 characteristics.go:59: 192.168.1.40:51444 GET /characteristics map[id:[19.7]]
DEBUG 2021/12/10 17:06:34 characteristics.go:59: 192.168.1.40:51444 GET /characteristics map[id:[1.7]]
...

[gisbertpeter]

@gisbertpeter The last log message looks suspicious. I've never seen a request for negative id values. Do you know what device on your network has the IP address 192.168.0.53?

@brutella The device 192.168.0.53 is the Raspberry PI where HKKNX runs on.

[dotgrid]

@brutella I was able to capture more of the debug log. Crucially, this log covers a period when all my hnknx devices became unavailable.

The full log is saved as a gist, since it's quite large.

Lines 342–363 are possibly the most interesting.

@brutella I had difficulties today that were less severe. This time, some commands from HomeKit --> hkknx would work, but with a ~60 second delay. More often, commands didn't run and devices continued to read Not Responsive in the Home app.

Here's the debug log during the 25-minute period I had problems.

[brutella]

@brutella The device 192.168.0.53 is the Raspberry PI where HKKNX runs on.

@gisbertpeter Which Homebridge plugins are running on the Raspberry Pi? Please try to disable Homebridge on that computer and check if the connection issues still persist.

[brutella]

@paulfarnell What iOS device on your network has the IP address 192.168.1.40?

[dotgrid]

@paulfarnell What iOS device on your network has the IP address 192.168.1.40?

@brutella That is an Apple TV HD device (not the latest Apple TV 4K).

[gisbertpeter]

@brutella The only Homebrigde Plugin is zigbee2mqtt

[dotgrid]

@brutella I noticed some new items in the debug log today (hkknx devices continue to be unresponsive). Note that Homebridge is no longer running on my system.

DEBUG 2021/12/13 23:08:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[25.7]]
DEBUG 2021/12/13 23:08:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[7.7]]
DEBUG 2021/12/13 23:08:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[24.7]]
DEBUG 2021/12/13 23:08:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[22.7]]
2021/12/13 23:08:25 discarding message with sequence number 2 (expected 3)
DEBUG 2021/12/13 23:08:30 connection.go:112: Close connection and remove session
DEBUG 2021/12/13 23:08:30 connection.go:112: Close connection and remove session
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":18,"iid":10,"ev":true},{"aid":18,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":37,"iid":10,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":32,"iid":10,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":3,"iid":10,"ev":true},{"aid":3,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":2,"iid":10,"ev":true},{"aid":2,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":38,"iid":10,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":14,"iid":10,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":23,"iid":10,"ev":true},{"aid":23,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":10,"iid":10,"ev":true},{"aid":10,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":15,"iid":10,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":20,"iid":10,"ev":true},{"aid":20,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":7,"iid":10,"ev":true},{"aid":7,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":25,"iid":10,"ev":true},{"aid":25,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":4,"iid":10,"ev":true},{"aid":4,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":41,"iid":10,"ev":true},{"aid":41,"iid":11,"ev":true},{"aid":41,"iid":12,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":11,"iid":10,"ev":true},{"aid":11,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":29,"iid":10,"ev":true},{"aid":29,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":22,"iid":10,"ev":true},{"aid":22,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":17,"iid":10,"ev":true},{"aid":17,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":28,"iid":10,"ev":true},{"aid":28,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":8,"iid":10,"ev":true},{"aid":8,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":12,"iid":10,"ev":true},{"aid":12,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":21,"iid":10,"ev":true},{"aid":21,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":13,"iid":10,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":40,"iid":10,"ev":true},{"aid":40,"iid":11,"ev":true},{"aid":40,"iid":12,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":24,"iid":10,"ev":true},{"aid":24,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":26,"iid":10,"ev":true},{"aid":26,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":39,"iid":10,"ev":true},{"aid":39,"iid":11,"ev":true},{"aid":39,"iid":12,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":6,"iid":10,"ev":true},{"aid":6,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":36,"iid":10,"ev":true}]}
DEBUG 2021/12/13 23:08:31 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:31 characteristics.go:107: {"characteristics":[{"aid":19,"iid":10,"ev":true},{"aid":19,"iid":11,"ev":true}]}
DEBUG 2021/12/13 23:08:41 characteristics.go:102: 192.168.1.74:59306 PUT /characteristics
DEBUG 2021/12/13 23:08:41 characteristics.go:107: {"characteristics":[{"aid":32,"iid":10,"ev":true}]}
DEBUG 2021/12/13 23:09:15 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[10.11]]
DEBUG 2021/12/13 23:09:15 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[37.10,19.10,19.11,10.10,23.11,23.10,12.10,12.11,28.10,28.11,2.10,2.11,15.10,26.10,26.11,22.11,22.10,18.10,18.11,21.11,21.10,4.11,4.10,32.10,6.10,6.11,25.11,25.10,7.10,7.11,38.10,41.10,41.11,17.10,17.11,11.11,11.10,40.10,40.11,3.11,3.10,20.10,20.11,8.11,8.10,24.10,24.11,39.10,39.11,14.10,36.10,13.10,29.11,29.10]]
DEBUG 2021/12/13 23:09:15 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[21.11,21.10,20.11,20.10,19.11,19.10,13.10,29.11,29.10,2.10,2.11,4.10,4.11,28.10,28.11,8.10,8.11,14.10]]
2021/12/13 23:09:19 discarding message with sequence number 16 (expected 17)
2021/12/13 23:09:20 discarding message with sequence number 20 (expected 21)
2021/12/13 23:09:21 discarding message with sequence number 51 (expected 52)
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[22.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[8.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[20.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[24.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[29.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[10.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[4.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[26.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[18.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[37.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[14.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[13.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[32.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[28.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[41.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[40.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[7.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[11.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[6.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[1.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[15.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[38.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[23.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[12.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[36.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[19.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[17.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[25.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[3.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[39.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[2.7]]
DEBUG 2021/12/13 23:09:22 characteristics.go:59: 192.168.1.74:59306 GET /characteristics map[id:[21.7]]
2021/12/13 23:09:22 discarding message with sequence number 56 (expected 57)
2021/12/13 23:09:24 discarding message with sequence number 70 (expected 71)
2021/12/13 23:09:26 discarding message with sequence number 94 (expected 95)
2021/12/13 23:09:27 discarding message with sequence number 110 (expected 111)
2021/12/13 23:10:18 discarding message with sequence number 150 (expected 151)

[dotgrid]

@brutella I just restarted hkknx and saw some messages that might be helpful? I have no idea if this is useful or not 🙂

$ ./hkknx -db ./database --verbose
INFO 2021/12/13 23:15:44 main.go:79: version 2.1.0 (built at 2021-11-08T13:57:09Z+0100)
INFO 2021/12/13 23:15:44 main.go:220: webpage available at port 8080
INFO 2021/12/13 23:15:46 app.go:321: tunnel: connected to 192.168.1.59:3671 via 1.8.3
DEBUG 2021/12/13 23:15:46 app.go:402: ntp: disabled
DEBUG 2021/12/13 23:15:46 io.go:15: read: 1/2/3
DEBUG 2021/12/13 23:15:46 io.go:15: read: 1/2/4
DEBUG 2021/12/13 23:15:46 io.go:15: read: 2/0/8
DEBUG 2021/12/13 23:15:46 io.go:15: read: 2/0/9
INFO 2021/12/13 23:15:47 io.go:22: read 2/0/9: group read: timeout
DEBUG 2021/12/13 23:15:47 io.go:15: read: 2/0/13
INFO 2021/12/13 23:15:47 io.go:22: read 2/0/13: group read: timeout
DEBUG 2021/12/13 23:15:47 io.go:15: read: 2/0/14
2021/12/13 23:15:47 discarding message with sequence number 5 (expected 6)
DEBUG 2021/12/13 23:15:47 io.go:15: read: 1/0/8
DEBUG 2021/12/13 23:15:47 io.go:15: read: 1/0/9
DEBUG 2021/12/13 23:15:47 io.go:15: read: 2/0/23
DEBUG 2021/12/13 23:15:47 io.go:15: read: 2/0/24
DEBUG 2021/12/13 23:15:47 io.go:15: read: 2/0/28
DEBUG 2021/12/13 23:15:47 io.go:15: read: 2/0/29
DEBUG 2021/12/13 23:15:48 io.go:15: read: 2/0/43
INFO 2021/12/13 23:15:48 io.go:22: read 2/0/43: group read: timeout
DEBUG 2021/12/13 23:15:48 io.go:15: read: 2/0/44
INFO 2021/12/13 23:15:49 io.go:22: read 2/0/44: group read: timeout
DEBUG 2021/12/13 23:15:49 io.go:15: read: 1/0/13
2021/12/13 23:15:49 discarding message with sequence number 25 (expected 26)
DEBUG 2021/12/13 23:15:49 io.go:15: read: 1/0/14
DEBUG 2021/12/13 23:15:49 io.go:15: read: 1/1/3
DEBUG 2021/12/13 23:15:49 io.go:15: read: 1/1/4
DEBUG 2021/12/13 23:15:49 io.go:15: read: 1/2/8
INFO 2021/12/13 23:15:49 io.go:22: read 1/2/8: group read: timeout
DEBUG 2021/12/13 23:15:49 io.go:15: read: 1/2/13
INFO 2021/12/13 23:15:50 io.go:22: read 1/2/13: group read: timeout
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/3/3
2021/12/13 23:15:50 discarding message with sequence number 38 (expected 39)
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/3/13
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/3/14
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/4/3
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/4/4
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/5/3
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/5/4
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/5/8
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/5/9
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/5/28
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/5/29
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/5/33
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/5/34
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/6/3
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/6/4
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/6/8
DEBUG 2021/12/13 23:15:50 io.go:15: read: 1/6/9
DEBUG 2021/12/13 23:15:51 io.go:15: read: 1/6/13
INFO 2021/12/13 23:15:51 io.go:22: read 1/6/13: group read: timeout
DEBUG 2021/12/13 23:15:51 io.go:15: read: 1/6/14
INFO 2021/12/13 23:15:52 io.go:22: read 1/6/14: group read: timeout
DEBUG 2021/12/13 23:15:52 io.go:15: read: 1/6/18
2021/12/13 23:15:52 discarding message with sequence number 76 (expected 77)
DEBUG 2021/12/13 23:15:52 io.go:15: read: 1/6/19
DEBUG 2021/12/13 23:15:52 io.go:15: read: 1/7/8
DEBUG 2021/12/13 23:15:52 io.go:15: read: 1/7/9
DEBUG 2021/12/13 23:15:52 io.go:15: read: 1/7/13
DEBUG 2021/12/13 23:15:52 io.go:15: read: 1/7/14
DEBUG 2021/12/13 23:15:52 io.go:15: read: 1/6/50
DEBUG 2021/12/13 23:15:52 io.go:15: read: 2/0/50
DEBUG 2021/12/13 23:15:52 io.go:15: read: 1/5/50
DEBUG 2021/12/13 23:15:52 io.go:15: read: 1/0/50
DEBUG 2021/12/13 23:15:52 io.go:15: read: 3/0/3
DEBUG 2021/12/13 23:15:52 io.go:15: read: 3/0/8
DEBUG 2021/12/13 23:15:52 io.go:15: read: 3/0/13
INFO 2021/12/13 23:15:52 ip_transport.go:184: Listening on port 51249
DEBUG 2021/12/13 23:15:55 pair-verify.go:37: 192.168.1.74:59325 POST /pair-verify
DEBUG 2021/12/13 23:15:55 pair-verify.go:44: Create new pair verify controller
DEBUG 2021/12/13 23:15:55 verify_server_controller.go:93: ->     A: 7aa62f0ffd725b41d2876e3a2c288cab7341fd3654dd628c28c36bd485dea03d
DEBUG 2021/12/13 23:15:55 verify_server_controller.go:127:        K: e2ae36c44fe3577a8dd8e358fc5242ca3305467faac1d8916bdec48642c3f213
DEBUG 2021/12/13 23:15:55 verify_server_controller.go:128:        B: 2f422ac6a977ce997ec173bff6baa2423d3753d26c42b9140101fe803711df35
DEBUG 2021/12/13 23:15:55 verify_server_controller.go:129:        S: 40fcec59e3ef5ff442adea3fe3e8e89088619fa0d2a94529c39181c78baa504d
DEBUG 2021/12/13 23:15:55 verify_server_controller.go:130:   Shared: 977add4ad927327abad2bd67986e8ce7035c30dbd0d6061a38221d04c446c30f
DEBUG 2021/12/13 23:15:55 verify_server_controller.go:132: <-     B: 2f422ac6a977ce997ec173bff6baa2423d3753d26c42b9140101fe803711df35
DEBUG 2021/12/13 23:15:55 pair-verify.go:37: 192.168.1.74:59325 POST /pair-verify
DEBUG 2021/12/13 23:15:55 verify_server_controller.go:152: ->     Message: d96a2783be8d47851432d3910f21f69e1c30160350b001e71b820b016025d673e69c69151a236cfca4e7e44e8631c90013f809725d541103fcf5ae7e7a275b5b24caf6d5ecc89a92f209d2b244886db6d37f634e60a58814c93c9bef0687b1823fcc1e9c0847c6a5
DEBUG 2021/12/13 23:15:55 verify_server_controller.go:153: ->     MAC: 1daeb39b28d56d3003190ea4d0bf4c5f
DEBUG 2021/12/13 23:15:55 verify_server_controller.go:172:     client: 7FFB5D3C-FA0D-44DA-882D-BC7657920054
DEBUG 2021/12/13 23:15:55 verify_server_controller.go:173:  signature: dcdcf98f4ad531e52cad54cb851e8b71c882bb98242b3fdca0c5ee5340a98c1f61bb5e9bc2a6c703ea287dd6e374f8ac210312426dd2aea0025031deb3c1fb06
DEBUG 2021/12/13 23:15:55 verify_server_controller.go:194: signature is valid
DEBUG 2021/12/13 23:15:55 pair-verify.go:70: Setup secure session
DEBUG 2021/12/13 23:15:55 accessories.go:13: 192.168.1.74:59325 GET /accessories

[brutella]

@paulfarnell What KNX IP Gateway are you using, and how is hkknx connected to it (via Ethernet or Wifi)? Also, is hkknx connected to your local network via Ethernet or Wifi?

[dotgrid]

@brutella Hi, thanks again for your assistance!

The KNX IP gateway is a 1home "Bridge" device on the KNX bus, wired to the local network via ethernet. hkknx runs on an M1 Mac Mini connected via ethernet.

If it helps, the 1home and the Mac Mini are on the same subnet, and even on the same physical network switch.

[hr-automation]

Same messages on MDT SCN-IP000.03 IP Interface as shown here: https://github.com/brutella/hkknx-public/issues/150#issuecomment-988937905

[gisbertpeter]

@brutella - status update: since Dec 11th HKKNX worked without any problems with the HomeKit connection. Unfortunarely this night HKKNX becomes unresponsive again. I had to reboot the Raspberry.

Note: in parallel a node-red flow runs using the knxEasy and homekit-bridged plugins. This has no problem connecting the KNX bus by Homekit.

[brutella]

@gisbertpeter Do you have any logs from hkknx you can share? Do you have any scripts running?

[gisbertpeter]

@brutella Unfortunately for this I don‘t have log, sorry foregotten. Scripts aren‘t running. I‘ll now connect the Raspberry to Ethernet instead of WLAN, then monitor again.

[hr-automation]

@gisbertpeter Any news about your new local changes?

[gisbertpeter]

@hr-automation no news, after changing from WLAN to LAN hkknx didn‘t work with a new IP address without reconfiguring Homekit. Due to the limited time available I have to try it again later. But in between HKKNX was unresponsive again :-(

[hr-automation]

Thanks to getting back to this issue. So the question is going back to @brutella ;-)

i can give you all my logs i have, BUT as i described before, i reboot every day my Pi!!

[gisbertpeter]

@brutella I assume that you have a KNX system for testing. Have you ever seen the problem with your KNX system? Is the problem possibly available with a new HKKNX version only? I have only the experience with v2 since beginning of October.

[dotgrid]

@brutella Any advice or anything else I can try for my installation? I am thinking I may need to switch away from hkknx to a different tool if I can't get a resolution in the next week or two. ☹️

[gisbertpeter]

@brutella Question: why it is possible to connect by the HKKNX Web-frontend when I have stoped the HKKNX Service? … and this still shows „HomeKit bridge available“

pi@homebridge:~ $ sudo systemctl stop hkknxd.service pi@homebridge:~ $ sudo systemctl status hkknxd.service ● hkknxd.service - HomeKit Bridge for KNX Loaded: loaded (/etc/systemd/system/hkknxd.service; disabled; vendor preset: enabled) Active: inactive (dead)

Dec 23 10:47:21 homebridge systemd[1]: Stopped HomeKit Bridge for KNX. Dec 23 10:47:39 homebridge systemd[1]: Started HomeKit Bridge for KNX. Dec 23 10:47:39 homebridge hkknx[6748]: INFO 2021/12/23 10:47:39 main.go:79: version 2.1.1 (built at 2021-12-07T16:22:38Z+0100) Dec 23 10:47:39 homebridge hkknx[6748]: INFO 2021/12/23 10:47:39 main.go:220: webpage available at port 8080 Dec 23 10:53:07 homebridge hkknx[6748]: INFO 2021/12/23 10:53:07 main.go:213: shutting down... Dec 23 10:53:07 homebridge systemd[1]: Stopping HomeKit Bridge for KNX... Dec 23 10:53:09 homebridge hkknx[6748]: INFO 2021/12/23 10:53:09 main.go:193: app: stop Dec 23 10:53:09 homebridge hkknx[6748]: INFO 2021/12/23 10:53:09 main.go:226: good bye ;) Dec 23 10:53:09 homebridge systemd[1]: hkknxd.service: Succeeded. Dec 23 10:53:09 homebridge systemd[1]: Stopped HomeKit Bridge for KNX. pi@homebridge:~ $

[brutella]

I suspect that your specific network configuration leads to this problem, since other people do not experience this issue. I would suggest to do the following.

1. Make sure that your network meets the network requirements (see German articles in the Online Handbook → https://hochgatterer.me/de/hkknx/docs/config/knx-connection/). Specifically allow multicast and ports 5353 und 3671 on your network.
2. Run hkknx on a dedicated computer (without using Homebridge or knxd on the same machine)
3. Connect hkknx via Ethernet to your local network
4. Do not use any beta version on your iOS devices and Apple TVs.

[hr-automation]

A short feedback from my side between Christmas Holidays.

On my Sophos Firewall "NOW" i found an option to activate Multicast DNS. And as i can see, from 23/12/2021 up to today no problems. But i get -1 Messages in the log like: discarding message with sequence number 146 (expected 147) Any idea why this messages come over?

Thanks.

Best regards.

[brutella]

On my Sophos Firewall "NOW" i found an option to activate Multicast DNS. And as i can see, from 23/12/2021 up to today no problems.

Ok, so Multicast was disabled for your network. It this the same for @paulfarnell and @gisbertpeter as well?

But i get -1 Messages in the log like: discarding message with sequence number 146 (expected 147) Any idea why this messages come over?

This message is not an error. It happens when a message gets lost between the KNX IP Gateway and hkknx.

[brutella]

@paulfarnell @gisbertpeter Could you resolve the connection issue by following the steps from this post?

[gisbertpeter]

@brutella After connecting the Raspberry by LAN (instead of WLAN) I didn't had any disconnects to Homekit over at least 8 days (over christmas time). It was not longer possible to monitor because I had to reboot the Raspberry due to other reasons. I monitored also the memory usage of HKKNX task but I haven't observed any increase of the memory size used over time. Summary: A) I assume the LAN connection improves the operability. A WLAN connection should be avoided. B) Maybe the HKKNX automatic reconnect in case of a disconnect is detected to Homekit could be improved. But I don't know if this is technically possible. C) I will further monitor and inform you about any news.

[brutella]

B) Maybe the HKKNX automatic reconnect in case of a disconnect is detected to Homekit could be improved.

hkknx does this already.

---

Any update from @unsaltedorg ? Otherwise I see this issue as resolved.

[dotgrid]

Working for me now after fixing multicast on my network! Thank you!