This is my 3rd HA installation - after 1 year still getting random delays

maykino · October 31, 2020, 1:58am

Last time I asked on this forum about troubleshooting random delays between motion sensors and switches or dimmers somebody said to look at the Logbook. Okay, it just happened that I walked in the kitchen and it took 13 seconds for the light to turn on:

[Kitchen Dimmer] turned on 9:53:11 PM - 2 minutes ago

[MS Hallway 2?] turned off 9:53:01 PM - 2 minutes ago

[MS Kitchen] turned on 9:52:59 PM - 2 minutes ago

What is the next step to troubleshoot it? Things like this one happen to me all the time btw.

Also, here is the zwave log:

2020-10-30 21:52:59.777 Info, Node009, Received SecurityCmd_NonceGet from node 9
2020-10-30 21:52:59.777 Info, NONCES: 0xc8, 0xcb, 0x27, 0x09, 0xdf, 0xc5, 0xe0, 0x94
2020-10-30 21:52:59.777 Info, NONCES: 0x40, 0xcb, 0xf2, 0x87, 0x33, 0xee, 0xb4, 0xb3
2020-10-30 21:52:59.777 Info, NONCES: 0x88, 0xd6, 0x82, 0x9a, 0x96, 0x35, 0xfb, 0x68
2020-10-30 21:52:59.777 Info, NONCES: 0x1c, 0x82, 0xa2, 0x21, 0x93, 0x08, 0x47, 0x83
2020-10-30 21:52:59.778 Info, NONCES: 0x1e, 0x78, 0x00, 0x3f, 0xc9, 0x06, 0x20, 0xa7
2020-10-30 21:52:59.778 Info, NONCES: 0x18, 0xa3, 0x8e, 0xb9, 0x83, 0x4f, 0x87, 0x4e
2020-10-30 21:52:59.778 Info, NONCES: 0x65, 0x1b, 0x38, 0xa0, 0x55, 0x48, 0xa4, 0x74
2020-10-30 21:52:59.778 Info, NONCES: 0x16, 0x7d, 0x99, 0xae, 0x0d, 0x4a, 0xa5, 0x6e
2020-10-30 21:52:59.778 Info, Node009, Sending (Send) message (Callback ID=0x01, Expected Reply=0x04) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x09, 0x0a, 0x98, 0x80, 0x1e, 0x78, 0x00, 0x3f, 0xc9, 0x06, 0x20, 0xa7, 0x05, 0x01, 0xf3:
2020-10-30 21:52:59.786 Detail, Node003,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-10-30 21:52:59.786 Detail, Node003,   ZW_SEND_DATA delivered to Z-Wave stack
2020-10-30 21:52:59.803 Detail, Node003,   Received: 0x01, 0x07, 0x00, 0x13, 0x01, 0x00, 0x00, 0x02, 0xe8
2020-10-30 21:52:59.803 Detail, Node003,   ZW_SEND_DATA Request with callback ID 0x01 received (expected 0x01)
2020-10-30 21:52:59.803 Info, Node003, Request RTT 9075 Average Request RTT 4552
2020-10-30 21:52:59.827 Detail, Node009,   Received: 0x01, 0x1e, 0x00, 0x04, 0x00, 0x09, 0x18, 0x98, 0x81, 0x29, 0xb2, 0xb3, 0x95, 0x48, 0x9a, 0x53, 0x7b, 0xd1, 0xa9, 0xfe, 0x6f, 0x07, 0x1e, 0x34, 0x15, 0x5b, 0x30, 0x8d, 0x0b, 0x7a, 0xdd, 0x31
2020-10-30 21:52:59.827 Info, Raw: 0x98, 0x81, 0x29, 0xb2, 0xb3, 0x95, 0x48, 0x9a, 0x53, 0x7b, 0xd1, 0xa9, 0xfe, 0x6f, 0x07, 0x1e, 0x34, 0x15, 0x5b, 0x30, 0x8d, 0x0b, 0x7a, 0xdd, 0x31
2020-10-30 21:52:59.827 Detail, Node009, Decrypted Packet: 0x00, 0x30, 0x03, 0xff, 0x0c
2020-10-30 21:52:59.827 Detail,
2020-10-30 21:52:59.827 Info, Node009, Received SensorBinary report: Sensor:12 State=On
2020-10-30 21:52:59.827 Detail, Node009, Refreshed Value: old value=false, new value=true, type=bool
2020-10-30 21:52:59.827 Detail, Node009, Changes to this value are not verified
2020-10-30 21:52:59.827 Detail, Node009, Notification: ValueChanged
2020-10-30 21:52:59.938 Info, Node005, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Dimming Duration - 5 - 1 - 255
2020-10-30 21:52:59.938 Detail, Node005, Refreshed Value: old value=255, new value=255, type=byte
2020-10-30 21:52:59.938 Detail, Node005, Changes to this value are not verified
2020-10-30 21:52:59.938 Detail, Node005, Notification: ValueChanged
2020-10-30 21:52:59.939 Info, Node005, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Level - 0 - 1 - 255
2020-10-30 21:52:59.939 Info, Node005, SwitchMultilevel::Set - Setting to level 255
2020-10-30 21:52:59.939 Info, Node005,   Duration: Default
2020-10-30 21:52:59.939 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Set (Node=5): 0x01, 0x0b, 0x00, 0x13, 0x05, 0x04, 0x26, 0x01, 0xff, 0xff, 0x25, 0xbc, 0x58
2020-10-30 21:52:59.940 Detail, Node005, Queuing (Send) SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0xbd, 0x5e
2020-10-30 21:53:00.721 Error, Node003, ERROR: Dropping command, expected response not received after 2 attempt(s)
2020-10-30 21:53:00.721 Detail, Node003, Removing current message
2020-10-30 21:53:00.721 Detail, Node003, Notification: Notification - TimeOut
2020-10-30 21:53:00.722 Detail,
2020-10-30 21:53:00.722 Info, Node011, Processing (Send) Nonce Request message (Callback ID=0xb7, Expected Reply=0x13)
2020-10-30 21:53:00.722 Info, Node011, Sending (Send) message (Callback ID=0xb7, Expected Reply=0x13) - Nonce_Get(SwitchMultilevelCmd_Set) - 0x01, 0x09, 0x00, 0x13, 0x0b, 0x02, 0x98, 0x40, 0x05, 0x02:
2020-10-30 21:53:00.729 Detail, Node011,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-10-30 21:53:00.729 Detail, Node011,   ZW_SEND_DATA delivered to Z-Wave stack
2020-10-30 21:53:00.747 Detail, Node011,   Received: 0x01, 0x07, 0x00, 0x13, 0x02, 0x00, 0x00, 0x02, 0xeb
2020-10-30 21:53:00.747 Detail, Node011,   ZW_SEND_DATA Request with callback ID 0x02 received (expected 0x02)
2020-10-30 21:53:00.747 Info, Node011, Request RTT 24 Average Request RTT 186
2020-10-30 21:53:00.771 Detail, Node011,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x0b, 0x0a, 0x98, 0x80, 0x10, 0x66, 0xaa, 0xec, 0x87, 0x14, 0xbc, 0x82, 0x6f
2020-10-30 21:53:00.771 Info, Node011, Received SecurityCmd_NonceReport from node 11
2020-10-30 21:53:00.771 Info, Node011, Sending (Send) message (Callback ID=0xbe, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=11): 0x01, 0x0b, 0x00, 0x13, 0x0b, 0x04, 0x26, 0x01, 0xff, 0xff, 0x25, 0xbe, 0x54
2020-10-30 21:53:00.781 Detail, Node011,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-10-30 21:53:00.781 Detail, Node011,   ZW_SEND_DATA delivered to Z-Wave stack
2020-10-30 21:53:00.830 Detail, Node011,   Received: 0x01, 0x07, 0x00, 0x13, 0xbe, 0x00, 0x00, 0x06, 0x53
2020-10-30 21:53:00.830 Detail, Node011,   ZW_SEND_DATA Request with callback ID 0xbe received (expected 0xbe)
2020-10-30 21:53:00.830 Info, Node011, Request RTT 107 Average Request RTT 146
2020-10-30 21:53:00.830 Detail,   Expected callbackId was received
2020-10-30 21:53:00.830 Detail,   Expected reply was received
2020-10-30 21:53:00.830 Detail,   Message transaction complete
2020-10-30 21:53:00.830 Detail,
2020-10-30 21:53:00.830 Detail, Node011, Removing current message
2020-10-30 21:53:00.830 Detail,
2020-10-30 21:53:00.830 Info, Node011, Processing (Send) Nonce Request message (Callback ID=0xb8, Expected Reply=0x04)
2020-10-30 21:53:00.830 Info, Node011, Sending (Send) message (Callback ID=0xb8, Expected Reply=0x04) - Nonce_Get(SwitchMultilevelCmd_Get) - 0x01, 0x09, 0x00, 0x13, 0x0b, 0x02, 0x98, 0x40, 0x05, 0x02:
2020-10-30 21:53:00.837 Detail, Node011,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-10-30 21:53:00.837 Detail, Node011,   ZW_SEND_DATA delivered to Z-Wave stack
2020-10-30 21:53:00.854 Detail, Node011,   Received: 0x01, 0x07, 0x00, 0x13, 0x02, 0x00, 0x00, 0x02, 0xeb
2020-10-30 21:53:00.854 Detail, Node011,   ZW_SEND_DATA Request with callback ID 0x02 received (expected 0x02)
2020-10-30 21:53:00.854 Info, Node011, Request RTT 23 Average Request RTT 84
2020-10-30 21:53:00.877 Detail, Node011,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x0b, 0x0a, 0x98, 0x80, 0x6b, 0x08, 0x44, 0xa5, 0x15, 0x33, 0xdd, 0x75, 0xfe
2020-10-30 21:53:00.877 Info, Node011, Received SecurityCmd_NonceReport from node 11
2020-10-30 21:53:00.877 Info, Node011, Sending (Send) message (Callback ID=0xbf, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=11): 0x01, 0x09, 0x00, 0x13, 0x0b, 0x02, 0x26, 0x02, 0x25, 0xbf, 0x52
2020-10-30 21:53:00.889 Detail, Node011,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-10-30 21:53:00.889 Detail, Node011,   ZW_SEND_DATA delivered to Z-Wave stack
2020-10-30 21:53:00.908 Detail, Node011,   Received: 0x01, 0x07, 0x00, 0x13, 0xbf, 0x00, 0x00, 0x03, 0x57
2020-10-30 21:53:00.908 Detail, Node011,   ZW_SEND_DATA Request with callback ID 0xbf received (expected 0xbf)
2020-10-30 21:53:00.908 Info, Node011, Request RTT 77 Average Request RTT 80
2020-10-30 21:53:00.908 Detail,   Expected callbackId was received
2020-10-30 21:53:00.932 Detail, Node011,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x0b, 0x02, 0x98, 0x40, 0x22
2020-10-30 21:53:00.932 Info, Node011, Received SecurityCmd_NonceGet from node 11
2020-10-30 21:53:00.932 Info, NONCES: 0x1e, 0x26, 0x90, 0x1d, 0x4c, 0x49, 0xa4, 0x39
2020-10-30 21:53:00.932 Info, NONCES: 0xa0, 0xd4, 0x36, 0x5c, 0xed, 0xcf, 0xe5, 0x16
2020-10-30 21:53:00.932 Info, NONCES: 0x38, 0x16, 0x08, 0xcc, 0x84, 0xb7, 0x88, 0xc5
2020-10-30 21:53:00.932 Info, NONCES: 0x1b, 0x25, 0xc2, 0xe1, 0x23, 0x25, 0x03, 0xe9
2020-10-30 21:53:00.932 Info, NONCES: 0x2d, 0xc6, 0x64, 0x2a, 0xf1, 0xe3, 0x72, 0x63
2020-10-30 21:53:00.932 Info, NONCES: 0xb7, 0x6c, 0xaa, 0xfa, 0x7d, 0xb7, 0x27, 0x56
2020-10-30 21:53:00.932 Info, NONCES: 0x33, 0x4d, 0x14, 0x01, 0x32, 0x7c, 0xd5, 0x49
2020-10-30 21:53:00.932 Info, NONCES: 0xed, 0x83, 0x74, 0x81, 0x55, 0x9a, 0x69, 0xdd
2020-10-30 21:53:00.932 Info, Node011, Sending (Send) message (Callback ID=0x01, Expected Reply=0x04) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x0b, 0x0a, 0x98, 0x80, 0x33, 0x4d, 0x14, 0x01, 0x32, 0x7c, 0xd5, 0x49, 0x05, 0x01, 0x59:
2020-10-30 21:53:00.940 Detail, Node011,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-10-30 21:53:00.940 Detail, Node011,   ZW_SEND_DATA delivered to Z-Wave stack
2020-10-30 21:53:00.958 Detail, Node011,   Received: 0x01, 0x07, 0x00, 0x13, 0x01, 0x00, 0x00, 0x03, 0xe9
2020-10-30 21:53:00.958 Detail, Node011,   ZW_SEND_DATA Request with callback ID 0x01 received (expected 0x01)
2020-10-30 21:53:00.958 Info, Node011, Request RTT 127 Average Request RTT 103
2020-10-30 21:53:00.986 Detail, Node011,   Received: 0x01, 0x1d, 0x00, 0x04, 0x00, 0x0b, 0x17, 0x98, 0x81, 0x46, 0x50, 0x44, 0x11, 0x1a, 0x14, 0xcf, 0x20, 0x3a, 0xe5, 0xbe, 0x35, 0x33, 0xbc, 0x36, 0x58, 0x32, 0x1e, 0x8a, 0x50, 0xf5, 0xf7
2020-10-30 21:53:00.986 Info, Raw: 0x98, 0x81, 0x46, 0x50, 0x44, 0x11, 0x1a, 0x14, 0xcf, 0x20, 0x3a, 0xe5, 0xbe, 0x35, 0x33, 0xbc, 0x36, 0x58, 0x32, 0x1e, 0x8a, 0x50, 0xf5, 0xf7
2020-10-30 21:53:00.986 Detail, Node011, Decrypted Packet: 0x00, 0x26, 0x03, 0x41
2020-10-30 21:53:00.986 Detail,
2020-10-30 21:53:00.987 Info, Node011, Response RTT 156 Average Response RTT 309
2020-10-30 21:53:00.987 Info, Node011, Received SwitchMultiLevel report: level=65
2020-10-30 21:53:00.987 Detail, Node011, Refreshed Value: old value=65, new value=65, type=byte
2020-10-30 21:53:00.987 Detail, Node011, Changes to this value are not verified
2020-10-30 21:53:00.987 Detail, Node011,   Expected reply and command class was received
2020-10-30 21:53:00.987 Detail, Node011,   Message transaction complete
2020-10-30 21:53:00.987 Detail,
2020-10-30 21:53:00.987 Detail, Node011, Removing current message
2020-10-30 21:53:00.987 Detail, Node011, Notification: ValueChanged
2020-10-30 21:53:00.989 Detail,
2020-10-30 21:53:00.989 Info, Node010, Sending (Send) message (Callback ID=0xb9, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=10): 0x01, 0x0b, 0x00, 0x13, 0x0a, 0x04, 0x26, 0x01, 0xff, 0xff, 0x25, 0xb9, 0x52
2020-10-30 21:53:00.997 Detail, Node010,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-10-30 21:53:00.997 Detail, Node010,   ZW_SEND_DATA delivered to Z-Wave stack
2020-10-30 21:53:01.164 Detail, Node010,   Received: 0x01, 0x07, 0x00, 0x13, 0xb9, 0x00, 0x00, 0x11, 0x43
2020-10-30 21:53:01.164 Detail, Node010,   ZW_SEND_DATA Request with callback ID 0xb9 received (expected 0xb9)
2020-10-30 21:53:01.164 Info, Node010, Request RTT 176 Average Request RTT 1031
2020-10-30 21:53:01.165 Detail,   Expected callbackId was received
2020-10-30 21:53:01.165 Detail,   Expected reply was received
2020-10-30 21:53:01.165 Detail,   Message transaction complete
2020-10-30 21:53:01.165 Detail,
2020-10-30 21:53:01.165 Detail, Node010, Removing current message
2020-10-30 21:53:01.165 Detail,
2020-10-30 21:53:01.165 Info, Node010, Sending (Send) message (Callback ID=0xba, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=10): 0x01, 0x09, 0x00, 0x13, 0x0a, 0x02, 0x26, 0x02, 0x25, 0xba, 0x56
2020-10-30 21:53:01.173 Detail, Node010,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-10-30 21:53:01.173 Detail, Node010,   ZW_SEND_DATA delivered to Z-Wave stack
2020-10-30 21:53:01.240 Detail, Node011,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x0b, 0x02, 0x98, 0x40, 0x22
2020-10-30 21:53:01.240 Info, Node011, Received SecurityCmd_NonceGet from node 11
2020-10-30 21:53:01.240 Info, NONCES: 0x1e, 0x26, 0x90, 0x1d, 0x4c, 0x49, 0xa4, 0x39
2020-10-30 21:53:01.240 Info, NONCES: 0xa0, 0xd4, 0x36, 0x5c, 0xed, 0xcf, 0xe5, 0x16
2020-10-30 21:53:01.240 Info, NONCES: 0x38, 0x16, 0x08, 0xcc, 0x84, 0xb7, 0x88, 0xc5
2020-10-30 21:53:01.241 Info, NONCES: 0x1b, 0x25, 0xc2, 0xe1, 0x23, 0x25, 0x03, 0xe9
2020-10-30 21:53:01.241 Info, NONCES: 0x2d, 0xc6, 0x64, 0x2a, 0xf1, 0xe3, 0x72, 0x63
2020-10-30 21:53:01.241 Info, NONCES: 0xb7, 0x6c, 0xaa, 0xfa, 0x7d, 0xb7, 0x27, 0x56
2020-10-30 21:53:01.241 Info, NONCES: 0x33, 0x4d, 0x14, 0x01, 0x32, 0x7c, 0xd5, 0x49
2020-10-30 21:53:01.241 Info, NONCES: 0xc1, 0x69, 0x37, 0x51, 0x45, 0x4a, 0xc7, 0xd5
2020-10-30 21:53:01.241 Info, Node011, Sending (Send) message (Callback ID=0x01, Expected Reply=0x04) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x0b, 0x0a, 0x98, 0x80, 0xc1, 0x69, 0x37, 0x51, 0x45, 0x4a, 0xc7, 0xd5, 0x05, 0x01, 0x33:
2020-10-30 21:53:01.248 Detail, Node010,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-10-30 21:53:01.248 Detail, Node010,   ZW_SEND_DATA delivered to Z-Wave stack
2020-10-30 21:53:01.356 Detail, Node010,   Received: 0x01, 0x07, 0x00, 0x13, 0x01, 0x00, 0x00, 0x0b, 0xe1
2020-10-30 21:53:01.356 Detail, Node010,   ZW_SEND_DATA Request with callback ID 0x01 received (expected 0x01)
2020-10-30 21:53:01.356 Info, Node010, Request RTT 191 Average Request RTT 611
2020-10-30 21:53:01.364 Detail, Node020,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x14, 0x03, 0x30, 0x03, 0x00, 0xd6
2020-10-30 21:53:01.364 Detail,
2020-10-30 21:53:01.364 Info, Node020, Received SensorBinary report: Sensor:214 State=Off
2020-10-30 21:53:01.364 Detail, Node020, Refreshed Value: old value=true, new value=false, type=bool
2020-10-30 21:53:01.364 Detail, Node020, Changes to this value are not verified
2020-10-30 21:53:01.364 Detail, Node020, Notification: ValueChanged
2020-10-30 21:53:01.414 Detail, Node010,   Received: 0x01, 0x07, 0x00, 0x13, 0x01, 0x00, 0x00, 0x11, 0xfb
2020-10-30 21:53:01.414 Detail, Node010,   ZW_SEND_DATA Request with callback ID 0x01 received (expected 0x01)
2020-10-30 21:53:01.414 Info, Node010, Request RTT 249 Average Request RTT 430
2020-10-30 21:53:01.472 Detail, Node011,   Received: 0x01, 0x1d, 0x00, 0x04, 0x00, 0x0b, 0x17, 0x98, 0x81, 0xbc, 0xe8, 0xd1, 0x29, 0x05, 0xe4, 0x60, 0x1e, 0xc7, 0x37, 0x03, 0x42, 0xc1, 0x6f, 0x22, 0x84, 0x0f, 0xa6, 0x3c, 0x97, 0xf4, 0x9f
2020-10-30 21:53:01.472 Info, Raw: 0x98, 0x81, 0xbc, 0xe8, 0xd1, 0x29, 0x05, 0xe4, 0x60, 0x1e, 0xc7, 0x37, 0x03, 0x42, 0xc1, 0x6f, 0x22, 0x84, 0x0f, 0xa6, 0x3c, 0x97, 0xf4, 0x9f
2020-10-30 21:53:01.472 Detail, Node011, Decrypted Packet: 0x00, 0x26, 0x03, 0x41
2020-10-30 21:53:01.472 Detail,
2020-10-30 21:53:01.472 Info, Node011, Received SwitchMultiLevel report: level=65
2020-10-30 21:53:01.472 Detail, Node011, Refreshed Value: old value=65, new value=65, type=byte
2020-10-30 21:53:01.472 Detail, Node011, Changes to this value are not verified
2020-10-30 21:53:01.472 Detail, Node011, Notification: ValueChanged
2020-10-30 21:53:01.512 Detail, Node010,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x0a, 0x03, 0x26, 0x03, 0x48, 0x96
2020-10-30 21:53:01.512 Detail,
2020-10-30 21:53:01.512 Info, Node010, Response RTT 347 Average Response RTT 1281
2020-10-30 21:53:01.512 Info, Node010, Received SwitchMultiLevel report: level=72
2020-10-30 21:53:01.512 Detail, Node010, Refreshed Value: old value=72, new value=72, type=byte
2020-10-30 21:53:01.512 Detail, Node010, Changes to this value are not verified
2020-10-30 21:53:01.512 Detail, Node010, Notification: ValueChanged
2020-10-30 21:53:01.588 Detail, Node020,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x14, 0x0a, 0x71, 0x05, 0x00, 0x00, 0x00, 0xff, 0x07, 0x00, 0x00, 0x00, 0x79
2020-10-30 21:53:01.588 Detail,
2020-10-30 21:53:01.588 Info, Node020, Received Alarm report: type=0, level=0, sensorSrcID=0, type:Burglar event:0, status=255
2020-10-30 21:53:01.588 Detail, Node020, Refreshed Value: old value=0, new value=0, type=byte
2020-10-30 21:53:01.588 Detail, Node020, Changes to this value are not verified
2020-10-30 21:53:01.588 Detail, Node020, Refreshed Value: old value=0, new value=0, type=byte
2020-10-30 21:53:01.588 Detail, Node020, Changes to this value are not verified
2020-10-30 21:53:01.588 Detail, Node020, Refreshed Value: old value=0, new value=0, type=byte
2020-10-30 21:53:01.588 Detail, Node020, Changes to this value are not verified
2020-10-30 21:53:01.589 Detail, Node020, Refreshed Value: old value=8, new value=0, type=byte
2020-10-30 21:53:01.589 Detail, Node020, Changes to this value are not verified
2020-10-30 21:53:01.589 Detail, Node020, Notification: ValueChanged
2020-10-30 21:53:01.591 Detail, Node020, Notification: ValueChanged
2020-10-30 21:53:01.593 Detail, Node020, Notification: ValueChanged
2020-10-30 21:53:01.595 Detail, Node020, Notification: ValueChanged
2020-10-30 21:53:01.618 Detail, Node020,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x14, 0x0a, 0x71, 0x05, 0x00, 0x00, 0x00, 0xff, 0x07, 0x00, 0x00, 0x00, 0x79
2020-10-30 21:53:01.618 Detail,
2020-10-30 21:53:01.618 Info, Node020, Received Alarm report: type=0, level=0, sensorSrcID=0, type:Burglar event:0, status=255
2020-10-30 21:53:01.618 Detail, Node020, Refreshed Value: old value=0, new value=0, type=byte
2020-10-30 21:53:01.618 Detail, Node020, Changes to this value are not verified
2020-10-30 21:53:01.618 Detail, Node020, Refreshed Value: old value=0, new value=0, type=byte
2020-10-30 21:53:01.618 Detail, Node020, Changes to this value are not verified
2020-10-30 21:53:01.619 Detail, Node020, Refreshed Value: old value=0, new value=0, type=byte
2020-10-30 21:53:01.619 Detail, Node020, Changes to this value are not verified
2020-10-30 21:53:01.619 Detail, Node020, Refreshed Value: old value=0, new value=0, type=byte
2020-10-30 21:53:01.619 Detail, Node020, Changes to this value are not verified
2020-10-30 21:53:01.619 Detail, Node020, Notification: ValueChanged
2020-10-30 21:53:01.621 Detail, Node020, Notification: ValueChanged
2020-10-30 21:53:01.623 Detail, Node020, Notification: ValueChanged
2020-10-30 21:53:01.625 Detail, Node020, Notification: ValueChanged
2020-10-30 21:53:01.681 Detail, Node020,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x14, 0x0a, 0x71, 0x05, 0x00, 0x00, 0x00, 0xff, 0x07, 0x00, 0x00, 0x00, 0x79
2020-10-30 21:53:01.681 Detail,
2020-10-30 21:53:01.681 Info, Node020, Received Alarm report: type=0, level=0, sensorSrcID=0, type:Burglar event:0, status=255
2020-10-30 21:53:01.681 Detail, Node020, Refreshed Value: old value=0, new value=0, type=byte
2020-10-30 21:53:01.681 Detail, Node020, Changes to this value are not verified
2020-10-30 21:53:01.681 Detail, Node020, Refreshed Value: old value=0, new value=0, type=byte
2020-10-30 21:53:01.681 Detail, Node020, Changes to this value are not verified
2020-10-30 21:53:01.681 Detail, Node020, Refreshed Value: old value=0, new value=0, type=byte
2020-10-30 21:53:01.681 Detail, Node020, Changes to this value are not verified
2020-10-30 21:53:01.681 Detail, Node020, Refreshed Value: old value=0, new value=0, type=byte
2020-10-30 21:53:01.681 Detail, Node020, Changes to this value are not verified
2020-10-30 21:53:01.681 Detail, Node020, Notification: ValueChanged
2020-10-30 21:53:01.684 Detail, Node020, Notification: ValueChanged
2020-10-30 21:53:01.686 Detail, Node020, Notification: ValueChanged
2020-10-30 21:53:01.687 Detail, Node020, Notification: ValueChanged
2020-10-30 21:53:01.710 Detail, Node010,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x0a, 0x03, 0x26, 0x03, 0x48, 0x96
2020-10-30 21:53:01.710 Detail,
2020-10-30 21:53:01.710 Info, Node010, Response RTT 545 Average Response RTT 913
2020-10-30 21:53:01.710 Info, Node010, Received SwitchMultiLevel report: level=72
2020-10-30 21:53:01.710 Detail, Node010, Refreshed Value: old value=72, new value=72, type=byte
2020-10-30 21:53:01.710 Detail, Node010, Changes to this value are not verified
2020-10-30 21:53:01.710 Detail, Node010, Notification: ValueChanged
2020-10-30 21:53:11.188 Error, Node010, ERROR: Dropping command, expected response not received after 1 attempt(s)
2020-10-30 21:53:11.188 Detail, Node010, Removing current message
2020-10-30 21:53:11.188 Detail, Node010, Notification: Notification - TimeOut
2020-10-30 21:53:11.189 Detail,
2020-10-30 21:53:11.189 Info, Node005, Sending (Send) message (Callback ID=0xbc, Expected Reply=0x13) - SwitchMultilevelCmd_Set (Node=5): 0x01, 0x0b, 0x00, 0x13, 0x05, 0x04, 0x26, 0x01, 0xff, 0xff, 0x25, 0xbc, 0x58
2020-10-30 21:53:11.197 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-10-30 21:53:11.197 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2020-10-30 21:53:11.242 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0xbc, 0x00, 0x00, 0x05, 0x52
2020-10-30 21:53:11.242 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0xbc received (expected 0xbc)
2020-10-30 21:53:11.242 Info, Node005, Request RTT 53 Average Request RTT 71
2020-10-30 21:53:11.242 Detail,   Expected callbackId was received
2020-10-30 21:53:11.242 Detail,   Expected reply was received
2020-10-30 21:53:11.242 Detail,   Message transaction complete
2020-10-30 21:53:11.242 Detail,
2020-10-30 21:53:11.242 Detail, Node005, Removing current message
2020-10-30 21:53:11.242 Detail,
2020-10-30 21:53:11.242 Info, Node005, Sending (Send) message (Callback ID=0xbd, Expected Reply=0x04) - SwitchMultilevelCmd_Get (Node=5): 0x01, 0x09, 0x00, 0x13, 0x05, 0x02, 0x26, 0x02, 0x25, 0xbd, 0x5e
2020-10-30 21:53:11.253 Detail, Node005,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-10-30 21:53:11.253 Detail, Node005,   ZW_SEND_DATA delivered to Z-Wave stack
2020-10-30 21:53:11.327 Detail, Node005,   Received: 0x01, 0x07, 0x00, 0x13, 0xbd, 0x00, 0x00, 0x08, 0x5e
2020-10-30 21:53:11.327 Detail, Node005,   ZW_SEND_DATA Request with callback ID 0xbd received (expected 0xbd)
2020-10-30 21:53:11.327 Info, Node005, Request RTT 84 Average Request RTT 77
2020-10-30 21:53:11.327 Detail,   Expected callbackId was received
2020-10-30 21:53:11.410 Detail, Node005,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x05, 0x03, 0x26, 0x03, 0x01, 0xd0
2020-10-30 21:53:11.410 Detail,
2020-10-30 21:53:11.410 Info, Node005, Response RTT 167 Average Response RTT 163
2020-10-30 21:53:11.410 Info, Node005, Received SwitchMultiLevel report: level=1
2020-10-30 21:53:11.410 Detail, Node005, Refreshed Value: old value=0, new value=1, type=byte
2020-10-30 21:53:11.410 Detail, Node005, Changes to this value are not verified
2020-10-30 21:53:11.410 Detail, Node005,   Expected reply and command class was received
2020-10-30 21:53:11.410 Detail, Node005,   Message transaction complete
2020-10-30 21:53:11.410 Detail,
2020-10-30 21:53:11.410 Detail, Node005, Removing current message
2020-10-30 21:53:11.410 Detail, Node005, Notification: ValueChanged
2020-10-30 21:53:12.979 Detail, Node019,   Received: 0x01, 0x09, 0x00, 0x04, 0x00, 0x13, 0x03, 0x30, 0x03, 0x00, 0xd1
2020-10-30 21:53:12.979 Detail,```
type or paste code here

sota · November 1, 2020, 7:51am

That’s the ZWave log, I think they meant the Home Assistant Logbook where you’ll see when each sensor was triggered.

maykino · November 2, 2020, 4:50pm

Right, that is the thing above my zwave log.

sota · November 2, 2020, 5:25pm

Duh, must learn to read !
I’m no Z-Wave expert but It occasionally happened on my lights. Anyway, I’d need a bit more information - what type of devices are you using, and how is the light being triggered, ie. are you using an automation or a z-wave scene? Also, which device relates to each node number, I can see Node005 seems to setting something to level 255 just after Node009 senses motion, and Node003 reports a timeout.
If it only happens randomly, perhaps it’s routing? Are the motion sensors and the lights connected directly to the Z-Wave controller?
If you switch on the lights manually, do you get delays? I had most of my lighting automations on Node-Red which gave random triggering delays - moving to native HA automations made them instantaneous.
In any event, if it’s still there after several clean installations the problem is unlikely to be HA.

petro · November 2, 2020, 6:24pm

How many items are you polling? If the answer is “alot”, then you might get random slow downs.

firstof9 · November 3, 2020, 10:51pm

Likely your issue is the node has been included securely and now you’re causing 200% overhead in packets on a already slow RF network.

Unless you’re using one of those weird Fibaro devices that requires secure connections, exclude your switches and include them without the secure option ie: Add Node vs Add Secure Node

All this is assuming the node with problems is Node 11 since you didn’t specify.

maykino · November 4, 2020, 3:23pm

Oh I didn’t know that. So in general I should always go for non-secure unless otherwise specified by the manufacturer?

srwhite · November 4, 2020, 4:03pm

My rule of thumb is that unless encryption is needed to keep the device secure, I avoid it due to the added overhead. Those are usually permitter devices like locks and garage door openers as those things absolutely need to be as secure as possible.

But light switches, dimmers, and other sensors do not benefit from encryption because no sensitive information is conveyed in the messaging to the hub.

Polling is the devil, especially when the device is secured. Here’s an example polling request where you can see the added overhead from the security layer.

Insecure:

Hub ----(get)---> Device
Hub <---(ack)---- Device
Hub <--(report)-- Device
Hub ----(ack)---> Device

Secure:

Hub ---(nonce get)--> Device
Hub <-----(ack)------ Device
Hub <----(nonce)----- Device
Hub ------(ack)-----> Device
Hub --(secure get)--> Device
Hub <-----(ack)------ Device
Hub <----(report)---- Device
Hub ------(ack)-----> Device

Always pair without security whenever possible. If your network is largely Z-Wave Plus (100kbps) you might not notice the overhead as much. But regular Z-Wave is 40kbps, older devices operate at 9600bps… If that switch is using a slower route that isn’t helping the lag any.