Listener issue...

[aromanro]

For now I don't know why it's happening, but I'll try to explain what seems to be wrong.

I have several devices, with a couple of them I can reproduce it, for example a wall controller (four buttons) and a thermostat.

Pressing a button on the wall controller makes the listener receive a scene notification. It displays something like this:

Thread 7fd67b574700: accepted connection from 192.168.123.210:41230
Thread 7fd67b574700: wrote 7 bytes
5B039D0001

cmd_class: COMMAND_CLASS_CENTRAL_SCENE v3
cmd: CENTRAL_SCENE_NOTIFICATION
Sequence Number >
157
Properties1 >
Key Attributes Key Pressed 1 time: Reserved:: 00
Slow Refresh : false

Scene Number >
001
bytestream: 5b 03 9d 00 01

Thread 7fd67b574700: read 17 bytes

With tcpdump I can see two packets, like this:

13:44:43.794128 IP 192.168.123.210.41230 > adrian-X7DWA.41231: UDP, length 77
13:44:43.794177 IP adrian-X7DWA.41231 > 192.168.123.210.41230: UDP, length 61

If I press a button on the thermostat, the listener displays something like this:

Connected to 192.168.123.230

Thread 7fd67b574700: accepted connection from 192.168.123.230:41230
Thread 7fd67b574700: wrote 7 bytes
8F01030380032F06310501420A87028407

cmd_class: COMMAND_CLASS_MULTI_CMD v1
cmd: MULTI_CMD_ENCAP

and so on... I don't think it's relevant, but the problem is that while the connection with the thermostat is active, a press on the button of the wall controller is not received by the listener. I can see with tcpdump the 77 bytes packets being sent, but not the 61 bytes ones:

13:48:27.982357 IP 192.168.123.210.41230 > adrian-X7DWA.41231: UDP, length 77
13:48:29.265798 IP 192.168.123.210.41230 > adrian-X7DWA.41231: UDP, length 77
13:48:30.370554 IP 192.168.123.210.41230 > adrian-X7DWA.41231: UDP, length 77
13:48:30.626107 IP 192.168.123.230.41230 > adrian-X7DWA.41231: UDP, length 77

The log of the zipgateway (the March binary) contains something like this:

When it works:

257262814 DTLS for Classic node
257263490 ApplicationIpCommandHandler: Package is too small.
257265221 ApplicationCommandHandler 27->1 class 0x98 cmd 0x40 size 2
257265287 ApplicationCommandHandler 27->1 class 0x98 cmd 0x81 size 29
257265287 Authentication verified
257265288 ApplicationCommandHandler 27->1 class 0x60 cmd 0x0d size 9
257265289 ApplicationCommandHandler 27->1 class 0x5b cmd 0x03 size 5
257265290 Unhandled command 0x5b:0x03 from fd00:55fc:b136:d42::1b
257265294
257265295 Sending Unsolicited to IP app...
257265296 Sending Unsolicited2 to IP app...
257265297 Sending first attempt
257265298 Frame has no payload
257265299 queue_send_done to node 27 queue 1
257265299 DTLS for Classic node
257265348 Session timeout 0x17ab160
257265349 Closing DTLS connection

When it doesn't work (a connection already existing due of the thermostat key press):

257332607 ApplicationCommandHandler 27->1 class 0x98 cmd 0x40 size 2
257332673 ApplicationCommandHandler 27->1 class 0x98 cmd 0x81 size 29
257332674 Authentication verified
257332675 ApplicationCommandHandler 27->1 class 0x60 cmd 0x0d size 9
257332675 ApplicationCommandHandler 27->1 class 0x5b cmd 0x03 size 5
257332676 Unhandled command 0x5b:0x03 from fd00:55fc:b136:d42::1b
257332680
257332681 Sending Unsolicited to IP app...
257332682 New client session allocated
257332683 Sending Unsolicited2 to IP app...
257332684 New client session allocated
257333182 GetCacheEntryFlag: on non existing node=0
257333183 Sending with scheme 255
257335685 Session timeout 0x17c1c40
257335686 Closing DTLS connection
257335687 Session timeout 0x17e1d28
257335688 Closing DTLS connection

I'll try to figure out more, if I'll find something new I'll add it here.

[aromanro]

More info: Today when I attempted to reproduce it again (after restarting the zip gateway), it worked all right for the above mentioned devices, but the problem occurred for another one.

Each time it's happening I see the GetCacheEntryFlag: on non existing node=0 log message.

[aromanro]

I have more info on it and a possible fix:

First I changed a timeout from 100 ms to 10 ms (see here: https://github.com/Z-WavePublic/libzwaveip/blob/master/libzwaveip/libzwaveip.c#L476 ) for listener connections only (checking is_client). This change made it behave much better, which offered a hint for the solution.

Currently in my code I have it set to 30 ms, but the solution I picked was to expose max_timeouts to be able to change it in the equivalent of zconnection_recv_raw and set it to zero to end the loop if a packet is received (alternatively, use is_running).
Basically I signal termination after calling recv here - only for a listener loop, of course, so is_client is checked: https://github.com/Z-WavePublic/libzwaveip/blob/master/libzwaveip/zconnection.c#L176

Sorry for the cryptic description, I changed the code into some C++ code I wrote which is quite different now than this one...

After this change I seem to receive all (most?) of notifications.