search

brutella / hkknx-public

hkknx is a HomeKit KNX bridge for KNX.
https://hochgatterer.me/hkknx
98 stars 6 forks source link

Sporadic Crashes #65

Closed BugRoger closed 3 years ago

BugRoger commented 3 years ago

My HKKNX process is dying every once in a while. I managed to catch the following panic. 

INFO 2020/09/12 10:21:37 main.go:64: version 1.1.0 (built at 2020-06-12T16:15:41Z+0200)
INFO 2020/09/12 10:21:37 main.go:183: webpage available at port 8080
DEBUG 2020/09/12 10:21:43 io.go:12: read: 1/2/21
DEBUG 2020/09/12 10:21:43 io.go:12: read: 4/5/0
DEBUG 2020/09/12 10:21:43 io.go:12: read: 4/5/0
DEBUG 2020/09/12 10:21:43 io.go:12: read: 7/1/0
DEBUG 2020/09/12 10:21:43 io.go:12: read: 7/1/2
DEBUG 2020/09/12 10:21:43 io.go:12: read: 7/1/1
DEBUG 2020/09/12 10:21:45 io.go:16: read: group read: timeout
DEBUG 2020/09/12 10:21:45 io.go:12: read: 7/1/7
DEBUG 2020/09/12 10:21:45 io.go:12: read: 7/2/7
2020/09/12 10:21:46 sequence number one less than expected
panic: send on closed channel

goroutine 53 [running]:
github.com/brutella/knx/knxnet.(*link).publishMsg(0xc0000fdc00, 0xffb900, 0xc000156180)
    /Users/mah/Source/Code/Go/src/github.com/brutella/knx/knxnet/link.go:221 +0x4d
created by github.com/brutella/knx/knxnet.(*link).GroupRead
    /Users/mah/Source/Code/Go/src/github.com/brutella/knx/knxnet/link.go:208 +0x149
panic: send on closed channel

goroutine 64 [running]:
github.com/brutella/knx/knxnet.(*link).publishMsg(0xc0000fdc00, 0xffb900, 0xc000156700)
    /Users/mah/Source/Code/Go/src/github.com/brutella/knx/knxnet/link.go:221 +0x4d
created by github.com/brutella/knx/knxnet.(*link).GroupRead
    /Users/mah/Source/Code/Go/src/github.com/brutella/knx/knxnet/link.go:208 +0x149

I usually notice since my devices show up as "No Response" in Homekit. Checking the GUI gives me a "System unavailable". After a while it stabilises again.

There's a similar error in the logs that might be related but doesn't cause a panic:

EBUG 2020/09/12 10:33:08 characteristics.go:48: 192.168.0.67:56765 PUT /characteristics
DEBUG 2020/09/12 10:33:08 characteristic_controller.go:76: {"characteristics":[{"aid":18,"iid":10,"ev":true}]}
2020/09/12 10:35:04 sequence number one less than expected
INFO 2020/09/12 10:35:04 app.go:232: stopping HomeKit...
DEBUG 2020/09/12 10:35:04 connection.go:112: Close connection and remove session
DEBUG 2020/09/12 10:35:04 connection.go:73: Decryption failed: read tcp 192.168.0.15:33167->192.168.0.86:58278: use of closed network connection
DEBUG 2020/09/12 10:35:04 connection.go:112: Close connection and remove session
DEBUG 2020/09/12 10:35:04 connection.go:112: Close connection and remove session
DEBUG 2020/09/12 10:35:04 connection.go:73: Decryption failed: read tcp 192.168.0.15:33167->192.168.0.67:56765: use of closed network connection
DEBUG 2020/09/12 10:35:04 connection.go:112: Close connection and remove session
DEBUG 2020/09/12 10:35:04 connection.go:112: Close connection and remove session
DEBUG 2020/09/12 10:35:04 connection.go:73: Decryption failed: read tcp 192.168.0.15:33167->192.168.0.186:50655: use of closed network connection
DEBUG 2020/09/12 10:35:04 connection.go:112: Close connection and remove session
DEBUG 2020/09/12 10:35:04 connection.go:112: Close connection and remove session
DEBUG 2020/09/12 10:35:04 connection.go:73: Decryption failed: read tcp 192.168.0.15:33167->192.168.0.17:51501: use of closed network connection
DEBUG 2020/09/12 10:35:04 connection.go:112: Close connection and remove session
DEBUG 2020/09/12 10:35:04 connection.go:112: Close connection and remove session
DEBUG 2020/09/12 10:35:04 connection.go:73: Decryption failed: read tcp 192.168.0.15:33167->192.168.0.208:49221: use of closed network connection
DEBUG 2020/09/12 10:35:04 connection.go:112: Close connection and remove session
DEBUG 2020/09/12 10:35:04 ip_transport.go:191: server stopped
DEBUG 2020/09/12 10:35:04 ip_transport.go:169: mdns responder stopped
DEBUG 2020/09/12 10:35:04 main.go:147: app: tunnel closed; retrying in 5s
DEBUG 2020/09/12 10:35:15 io.go:12: read: 1/2/21
DEBUG 2020/09/12 10:35:15 io.go:12: read: 4/5/0
DEBUG 2020/09/12 10:35:15 io.go:12: read: 4/5/0
DEBUG 2020/09/12 10:35:15 io.go:12: read: 7/1/0
DEBUG 2020/09/12 10:35:16 io.go:12: read: 7/1/2
DEBUG 2020/09/12 10:35:16 io.go:12: read: 7/1/1
DEBUG 2020/09/12 10:35:17 io.go:16: read: group read: timeout
DEBUG 2020/09/12 10:35:17 io.go:12: read: 7/1/7
DEBUG 2020/09/12 10:35:17 io.go:12: read: 7/2/7
DEBUG 2020/09/12 10:35:17 io.go:12: read: 7/2/0
DEBUG 2020/09/12 10:35:17 io.go:12: read: 7/2/1
DEBUG 2020/09/12 10:35:17 io.go:12: read: 7/2/2
DEBUG 2020/09/12 10:35:17 io.go:12: read: 7/2/3
DEBUG 2020/09/12 10:35:17 io.go:12: read: 7/2/4
DEBUG 2020/09/12 10:35:17 io.go:12: read: 7/2/5
DEBUG 2020/09/12 10:35:17 io.go:12: read: 7/2/6
DEBUG 2020/09/12 10:35:17 io.go:12: read: 7/2/8
DEBUG 2020/09/12 10:35:17 io.go:12: read: 7/3/8
DEBUG 2020/09/12 10:35:17 io.go:12: read: 5/0/0
DEBUG 2020/09/12 10:35:17 io.go:12: read: 1/2/22
DEBUG 2020/09/12 10:35:17 io.go:12: read: 1/2/19
DEBUG 2020/09/12 10:35:17 io.go:12: read: 1/2/5
DEBUG 2020/09/12 10:35:19 io.go:12: read: 1/2/25
DEBUG 2020/09/12 10:35:19 io.go:12: read: 1/2/13
DEBUG 2020/09/12 10:35:19 io.go:12: read: 1/2/10
DEBUG 2020/09/12 10:35:19 io.go:12: read: 1/2/11
DEBUG 2020/09/12 10:35:19 io.go:12: read: 1/2/12
DEBUG 2020/09/12 10:35:19 io.go:12: read: 1/2/17
DEBUG 2020/09/12 10:35:19 io.go:12: read: 1/2/2
DEBUG 2020/09/12 10:35:19 io.go:12: read: 7/0/1
DEBUG 2020/09/12 10:35:19 io.go:12: read: 4/5/3
DEBUG 2020/09/12 10:35:19 io.go:12: read: 4/5/3
DEBUG 2020/09/12 10:35:19 io.go:12: read: 1/2/0
DEBUG 2020/09/12 10:35:19 io.go:12: read: 1/2/1
DEBUG 2020/09/12 10:35:19 io.go:12: read: 1/2/2
DEBUG 2020/09/12 10:35:19 io.go:12: read: 1/2/3
DEBUG 2020/09/12 10:35:19 io.go:12: read: 1/2/4
DEBUG 2020/09/12 10:35:20 io.go:12: read: 1/2/5
DEBUG 2020/09/12 10:35:20 io.go:12: read: 1/2/6
DEBUG 2020/09/12 10:35:20 io.go:12: read: 1/2/8
DEBUG 2020/09/12 10:35:21 io.go:16: read: group read: timeout
DEBUG 2020/09/12 10:35:21 io.go:12: read: 1/2/9
DEBUG 2020/09/12 10:35:22 io.go:16: read: group read: timeout
DEBUG 2020/09/12 10:35:22 io.go:12: read: 1/2/10
DEBUG 2020/09/12 10:35:22 io.go:12: read: 1/2/11
DEBUG 2020/09/12 10:35:22 io.go:12: read: 1/2/13
DEBUG 2020/09/12 10:35:22 io.go:12: read: 1/2/12
DEBUG 2020/09/12 10:35:22 io.go:12: read: 1/2/14
DEBUG 2020/09/12 10:35:22 io.go:12: read: 1/2/15
DEBUG 2020/09/12 10:35:22 io.go:12: read: 1/2/16
DEBUG 2020/09/12 10:35:22 io.go:12: read: 1/2/17
DEBUG 2020/09/12 10:35:22 io.go:12: read: 1/2/18
DEBUG 2020/09/12 10:35:23 io.go:16: read: group read: timeout
DEBUG 2020/09/12 10:35:23 io.go:12: read: 1/2/19
DEBUG 2020/09/12 10:35:23 io.go:12: read: 1/2/20
DEBUG 2020/09/12 10:35:23 io.go:12: read: 1/2/21
DEBUG 2020/09/12 10:35:23 io.go:12: read: 1/2/22
DEBUG 2020/09/12 10:35:23 io.go:12: read: 1/2/23
DEBUG 2020/09/12 10:35:24 io.go:16: read: group read: timeout
DEBUG 2020/09/12 10:35:24 io.go:12: read: 1/2/24
DEBUG 2020/09/12 10:35:25 io.go:16: read: group read: timeout
DEBUG 2020/09/12 10:35:25 io.go:12: read: 1/2/25
DEBUG 2020/09/12 10:35:26 io.go:12: read: 1/2/26
DEBUG 2020/09/12 10:35:27 io.go:16: read: group read: timeout
DEBUG 2020/09/12 10:35:27 io.go:12: read: 1/2/27
DEBUG 2020/09/12 10:35:28 io.go:16: read: group read: timeout
DEBUG 2020/09/12 10:35:28 io.go:12: read: 1/2/14
DEBUG 2020/09/12 10:35:28 io.go:12: read: 8/0/1
DEBUG 2020/09/12 10:35:29 io.go:16: read: group read: timeout
DEBUG 2020/09/12 10:35:29 io.go:12: read: 2/2/3
DEBUG 2020/09/12 10:35:29 io.go:12: read: 2/5/3
DEBUG 2020/09/12 10:35:29 io.go:12: read: 2/1/6
DEBUG 2020/09/12 10:35:31 io.go:16: read: group read: timeout
DEBUG 2020/09/12 10:35:31 io.go:12: read: 2/5/6
DEBUG 2020/09/12 10:35:31 io.go:12: read: 2/2/2
DEBUG 2020/09/12 10:35:31 io.go:12: read: 2/5/2
DEBUG 2020/09/12 10:35:31 io.go:12: read: 2/1/7
DEBUG 2020/09/12 10:35:32 io.go:16: read: group read: timeout
DEBUG 2020/09/12 10:35:32 io.go:12: read: 2/5/7
DEBUG 2020/09/12 10:35:32 io.go:12: read: 7/4/6
DEBUG 2020/09/12 10:35:32 io.go:12: read: 7/2/6
INFO 2020/09/12 10:35:32 ip_transport.go:184: Listening on port 40355
DEBUG 2020/09/12 10:35:48 pair-verify.go:37: 192.168.0.208:49222 POST /pair-verify
DEBUG 2020/09/12 10:35:48 pair-verify.go:44: Create new pair verify controller
DEBUG 2020/09/12 10:35:48 verify_server_controller.go:93: ->     A: 4bf545333594e2ca6af5e2c0ce728eea9465419e793c0458064570bb9801e604
DEBUG 2020/09/12 10:35:48 verify_server_controller.go:127:        K: 8b83a8e6c2281a5b69c5e153c41b647feac98401c373b085ed1890200c372868
DEBUG 2020/09/12 10:35:48 verify_server_controller.go:128:        B: d61b3f806010859f1dcde57b80bb3d8080448e1f7c789855542c4993f46a7750
DEBUG 2020/09/12 10:35:48 verify_server_controller.go:129:        S: 07145d8da86b832245de8b9ae787c61d895cb96bd3163532f8a99a19229073ce
DEBUG 2020/09/12 10:35:48 verify_server_controller.go:130:   Shared: 6cff9edfe2293a302d19f8147339b240ae261f2e3338d247cff39300f83b9912
DEBUG 2020/09/12 10:35:48 verify_server_controller.go:132: <-     B: d61b3f806010859f1dcde57b80bb3d8080448e1f7c789855542c4993f46a7750
DEBUG 2020/09/12 10:35:48 pair-verify.go:37: 192.168.0.208:49222 POST /pair-verify
DEBUG 2020/09/12 10:35:48 verify_server_controller.go:152: ->     Message: 71a9646bb64c5531b853301f81313b60b484f97d782ce7048658c85d56d11826a9a33d0dee674b7ca6c12cdd4393e879c90f053b63476e8cd35168c8dabd125548a96deaa626ab60b0ecc357013018e2282aacb9649d40517186542d115b71323584ae51761e5f3d
DEBUG 2020/09/12 10:35:48 verify_server_controller.go:153: ->     MAC: 6a3a62a9655eef6f3d8ff7c57e7bc841
DEBUG 2020/09/12 10:35:48 verify_server_controller.go:172:     client: 3697470D-E010-44FA-8B0D-FCDE5075136C
DEBUG 2020/09/12 10:35:48 verify_server_controller.go:173:  signature: 011183c6c4158df73926e87daebfd4ff2607b234460aa12f04388418a2886d0789816213cb9268d77d6d31714fde7c6f3bda496a2ee5a1aba14f6cd530064a06
DEBUG 2020/09/12 10:35:48 verify_server_controller.go:194: signature is valid
DEBUG 2020/09/12 10:35:48 pair-verify.go:70: Setup secure session
DEBUG 2020/09/12 10:35:48 accessories.go:34: 192.168.0.208:49222 GET /accessories

Any pointer's what's happening?

BugRoger commented 3 years ago

It seems to be related to the group read: timeouts. Interessting enough the addresses that time out aren't even used by any accessory.

Does HKKNX by chance read the whole middle group, like 1/2/*? Possibly a race condition for addresses that don't respond to read? The addresses it tries to read here aren't connected and won't respond ever.

image

I'll try to clean up, so that all adresses related to Homekit respond. Though I'm using a scheme where I just copy/paste per Room which leaves me with many spare/empty/"for future reference" GAs. So, this is an annoying task :/

BugRoger commented 3 years ago

I found a workaround. First, I actually made it that all GAs respond on the read request. That didn't help. A google search hinted that "sequence number one less than expected" is either a problem with an SAP BAPI call or the KNX IP Gateway is responding out of sequence. 😄

Disabling the KNX Gateway auto-detection and setting it to another IP Gateway fixed it. MDT IP Router is throwing this error. The gateway in the Elabnet Timerwolf works without a problem.