Autre exemple de perte d’information Z-Wave.
Ici, 3 modules :
- un capteur de porte Fibaro Door/Window 2 sécurisé,
- un détecteur de présence Fibaro Motion Sensor 2 non-sécurisé
- un dimmer Fibaro Dimmer 2 non-sécurisé
J’ai préféré commenter le log que de le mettre en pièce jointe pour faciliter la lecture.
À 18:49:15, j’ouvre la porte, le module galère un peu à communiquer mais j’ai bien Access Control event:22
2020-04-01 18:49:15.064 Info, Node056, Received SecurityCmd_NonceGet from node 56
2020-04-01 18:49:15.065 Info, NONCES: 0xcd, 0x36, 0xa8, 0x69, 0x8f, 0x17, 0x8d, 0x1a
2020-04-01 18:49:15.065 Info, NONCES: 0x25, 0xda, 0xed, 0x73, 0x56, 0xc7, 0xec, 0xf5
2020-04-01 18:49:15.065 Info, NONCES: 0x0b, 0xf6, 0xb6, 0xa1, 0x3b, 0x33, 0xe8, 0xe7
2020-04-01 18:49:15.065 Info, NONCES: 0x83, 0xc5, 0xa0, 0x28, 0x83, 0xc7, 0xd7, 0x64
2020-04-01 18:49:15.065 Info, NONCES: 0x5d, 0x8d, 0x93, 0xc9, 0x2c, 0xd7, 0x3a, 0xed
2020-04-01 18:49:15.065 Info, NONCES: 0xfc, 0x95, 0x8c, 0x46, 0x9b, 0x82, 0xde, 0x20
2020-04-01 18:49:15.065 Info, NONCES: 0x30, 0x30, 0xab, 0x34, 0x9f, 0x19, 0x52, 0x90
2020-04-01 18:49:15.065 Info, NONCES: 0xbf, 0x7b, 0x73, 0x60, 0x8a, 0x4b, 0x31, 0xc9
2020-04-01 18:49:15.065 Info, Node056, Sending (WakeUp) message (Callback ID=0x01, Expected Reply=0x00) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x38, 0x0a, 0x98, 0x80, 0x25, 0xda, 0xed, 0x73, 0x56, 0xc7, 0xec, 0xf5, 0x05, 0x01, 0x3a:
2020-04-01 18:49:15.078 Info, Node056, Received SecurityCmd_NonceGet from node 56
2020-04-01 18:49:15.086 Info, NONCES: 0xcd, 0x36, 0xa8, 0x69, 0x8f, 0x17, 0x8d, 0x1a
2020-04-01 18:49:15.087 Info, NONCES: 0x25, 0xda, 0xed, 0x73, 0x56, 0xc7, 0xec, 0xf5
2020-04-01 18:49:15.087 Info, NONCES: 0xb9, 0x57, 0x1c, 0xd4, 0x48, 0x6b, 0xd0, 0xbe
2020-04-01 18:49:15.087 Info, NONCES: 0x83, 0xc5, 0xa0, 0x28, 0x83, 0xc7, 0xd7, 0x64
2020-04-01 18:49:15.087 Info, NONCES: 0x5d, 0x8d, 0x93, 0xc9, 0x2c, 0xd7, 0x3a, 0xed
2020-04-01 18:49:15.087 Info, NONCES: 0xfc, 0x95, 0x8c, 0x46, 0x9b, 0x82, 0xde, 0x20
2020-04-01 18:49:15.087 Info, NONCES: 0x30, 0x30, 0xab, 0x34, 0x9f, 0x19, 0x52, 0x90
2020-04-01 18:49:15.087 Info, NONCES: 0xbf, 0x7b, 0x73, 0x60, 0x8a, 0x4b, 0x31, 0xc9
2020-04-01 18:49:15.087 Info, Node056, Sending (WakeUp) message (Callback ID=0x01, Expected Reply=0x00) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x38, 0x0a, 0x98, 0x80, 0xb9, 0x57, 0x1c, 0xd4, 0x48, 0x6b, 0xd0, 0xbe, 0x05, 0x01, 0xb8:
2020-04-01 18:49:15.088 Info, Node056, Received SecurityCmd_NonceGet from node 56
2020-04-01 18:49:15.088 Info, NONCES: 0xcd, 0x36, 0xa8, 0x69, 0x8f, 0x17, 0x8d, 0x1a
2020-04-01 18:49:15.088 Info, NONCES: 0x25, 0xda, 0xed, 0x73, 0x56, 0xc7, 0xec, 0xf5
2020-04-01 18:49:15.089 Info, NONCES: 0xb9, 0x57, 0x1c, 0xd4, 0x48, 0x6b, 0xd0, 0xbe
2020-04-01 18:49:15.089 Info, NONCES: 0x11, 0x7c, 0x45, 0x51, 0x36, 0xd6, 0xcb, 0x80
2020-04-01 18:49:15.089 Info, NONCES: 0x5d, 0x8d, 0x93, 0xc9, 0x2c, 0xd7, 0x3a, 0xed
2020-04-01 18:49:15.089 Info, NONCES: 0xfc, 0x95, 0x8c, 0x46, 0x9b, 0x82, 0xde, 0x20
2020-04-01 18:49:15.089 Info, NONCES: 0x30, 0x30, 0xab, 0x34, 0x9f, 0x19, 0x52, 0x90
2020-04-01 18:49:15.089 Info, NONCES: 0xbf, 0x7b, 0x73, 0x60, 0x8a, 0x4b, 0x31, 0xc9
2020-04-01 18:49:15.089 Info, Node056, Sending (WakeUp) message (Callback ID=0x01, Expected Reply=0x00) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x38, 0x0a, 0x98, 0x80, 0x11, 0x7c, 0x45, 0x51, 0x36, 0xd6, 0xcb, 0x80, 0x05, 0x01, 0x01:
2020-04-01 18:49:15.091 Warning, m_currentMsg was NULL when trying to set MaxSendAttempts
2020-04-01 18:49:15.091 Always,
2020-04-01 18:49:15.092 Always, Dumping queued log messages
2020-04-01 18:49:15.097 Always,
2020-04-01 18:49:15.097 Always,
2020-04-01 18:49:15.097 Always, End of queued log message dump
2020-04-01 18:49:15.097 Always,
2020-04-01 18:49:15.107 Info, Node100, Received Central Scene set from node 100: scene id=1 with key Attribute 2. Sending event notification.
2020-04-01 18:49:15.117 Info, Node100, Value::Set - COMMAND_CLASS_CENTRAL_SCENE - Button - 3 - 1 - true
2020-04-01 18:49:15.182 Warning, m_currentMsg was NULL when trying to set MaxSendAttempts
2020-04-01 18:49:15.182 Always,
2020-04-01 18:49:15.182 Always, Dumping queued log messages
2020-04-01 18:49:15.182 Always,
2020-04-01 18:49:15.182 Always,
2020-04-01 18:49:15.182 Always, End of queued log message dump
2020-04-01 18:49:15.182 Always,
2020-04-01 18:49:15.183 Info, Node100, Received Central Scene set from node 100: scene id=1 with key Attribute 1. Sending event notification.
2020-04-01 18:49:15.183 Info, Node100, Value::Set - COMMAND_CLASS_CENTRAL_SCENE - Button - 3 - 1 - false
2020-04-01 18:49:15.191 Warning, m_currentMsg was NULL when trying to set MaxSendAttempts
2020-04-01 18:49:15.191 Always,
2020-04-01 18:49:15.191 Always, Dumping queued log messages
2020-04-01 18:49:15.191 Always,
2020-04-01 18:49:15.191 Always,
2020-04-01 18:49:15.191 Always, End of queued log message dump
2020-04-01 18:49:15.191 Always,
2020-04-01 18:49:15.224 Info, Raw: 0x98, 0x81, 0x1d, 0x02, 0xbe, 0x93, 0x24, 0x3d, 0xc3, 0x33, 0xb9, 0x45, 0x43, 0x66, 0x1e, 0x06, 0x62, 0xcb, 0xab, 0xd3, 0x11, 0x50, 0x91, 0x93, 0x26, 0xc1, 0x71, 0xdb, 0x6a, 0x4b
2020-04-01 18:49:15.224 Info, Node056, Received Alarm report: type=0, level=0, sensorSrcID=0, type:Access Control event:22, status=255
J’entre dans le garage, le détecteur de mouvement me voit 0.3 seconde après.
2020-04-01 18:49:15.511 Info, Node129, Received Alarm report: type=0, level=0, sensorSrcID=0, type:Burglar event:8, status=255
2020-04-01 18:49:15.573 Info, Node129, Received SensorBinary report: Sensor:180 State=On
2020-04-01 18:49:15.588 Info, Node129, Received SensorBinary report: Sensor:188 State=On
À 18:49:20, un scénario se lance et envoie l’ordre d’allume la lumière.
[2020-04-01 18:49:20][SCENARIO] Exécution de la commande [Garage][Lumiere][Allumer]
Le contrôleur envoie la commande Z-Wave pour allumer la lumière.
2020-04-01 18:49:20.740 Info, Node092, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Level - 0 - 1 - \FF
2020-04-01 18:49:20.741 Info, Node092, SwitchMultilevel::Set - Setting to level 255
2020-04-01 18:49:20.741 Info, Node092, Duration: Default
2020-04-01 18:49:20.741 Info, Node092, Sending (Send) message (Callback ID=0x6f, Expected Reply=0x13) - MultiChannel Encapsulated (instance=1): SwitchMultilevelCmd_Set (Node=92): 0x01, 0x0f, 0x00, 0x13, 0x5c, 0x08, 0x60, 0x0d, 0x01, 0x01, 0x26, 0x01, 0xff, 0xff, 0x25, 0x6f, 0xb7
2020-04-01 18:49:20.767 Info, Node092, Request RTT 26 Average Request RTT 25
2020-04-01 18:49:20.768 Info, Node092, Sending (Refresh) message (Callback ID=0x70, Expected Reply=0x04) - MultiChannel Encapsulated (instance=1): SwitchMultilevelCmd_Get (Node=92): 0x01, 0x0d, 0x00, 0x13, 0x5c, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x26, 0x02, 0x25, 0x70, 0xa7
2020-04-01 18:49:20.794 Info, Node092, Request RTT 26 Average Request RTT 25
2020-04-01 18:49:20.805 Info, Node092, Response RTT 36 Average Response RTT 36
2020-04-01 18:49:20.805 Info, Node092, Received a MultiChannelEncap from node 92, endpoint 1 for Command Class COMMAND_CLASS_SWITCH_MULTILEVEL
2020-04-01 18:49:20.805 Info, Node092, Received SwitchMultiLevel report: level=79
2020-04-01 18:49:20.893 Info, Node092, Received SwitchMultiLevel report: level=99
2020-04-01 18:49:21.453 Info, Node092, Received SensorMultiLevel report from node 92, instance 1, Power: value=31.2W
2020-04-01 18:49:26.438 Info, Node092, Received SensorMultiLevel report from node 92, instance 1, Power: value=60.9W
À 18:49:22, je quitte la pièce et je ferme la porte.
2020-04-01 18:49:22.909 Info, Node056, Received SecurityCmd_NonceGet from node 56
2020-04-01 18:49:22.909 Info, NONCES: 0xcd, 0x36, 0xa8, 0x69, 0x8f, 0x17, 0x8d, 0x1a
2020-04-01 18:49:22.909 Info, NONCES: 0x25, 0xda, 0xed, 0x73, 0x56, 0xc7, 0xec, 0xf5
2020-04-01 18:49:22.909 Info, NONCES: 0xb9, 0x57, 0x1c, 0xd4, 0x48, 0x6b, 0xd0, 0xbe
2020-04-01 18:49:22.909 Info, NONCES: 0x11, 0x7c, 0x45, 0x51, 0x36, 0xd6, 0xcb, 0x80
2020-04-01 18:49:22.909 Info, NONCES: 0xad, 0x55, 0x4a, 0xa0, 0xd9, 0x93, 0x86, 0xfd
2020-04-01 18:49:22.909 Info, NONCES: 0xfc, 0x95, 0x8c, 0x46, 0x9b, 0x82, 0xde, 0x20
2020-04-01 18:49:22.910 Info, NONCES: 0x30, 0x30, 0xab, 0x34, 0x9f, 0x19, 0x52, 0x90
2020-04-01 18:49:22.910 Info, NONCES: 0xbf, 0x7b, 0x73, 0x60, 0x8a, 0x4b, 0x31, 0xc9
2020-04-01 18:49:22.910 Info, Node056, Sending (Refresh) message (Callback ID=0x01, Expected Reply=0x00) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x38, 0x0a, 0x98, 0x80, 0xad, 0x55, 0x4a, 0xa0, 0xd9, 0x93, 0x86, 0xfd, 0x05, 0x01, 0xf0:
Là, il manque des infos, j’aurais dû avoir quelque chose comme ceci avec un Access Control event:23
Info, Raw: 0x98, 0x81, 0x15, 0x4c, 0x70, 0xf7, 0x10, 0x03, 0x2d, 0xc2, 0xc5, 0x81, 0x76, 0xaa, 0x27, 0x2e, 0xd4, 0xf3, 0xa4, 0x63, 0xcd, 0xdd, 0xde, 0x39, 0xa4, 0xea, 0xcb, 0xde, 0x5b, 0x40
Info, Node056, Received Alarm report: type=0, level=0, sensorSrcID=0, type:Access Control event:23, status=255
Donc, le module de porte a bien envoyé quelque chose, le controleur ne decode pas tout.
Résultat, la porte est toujours ouverte et non pas fermée pour Jeedom.
30 secondes plus tard, à 18:49:46, le détecteur de mouvement retombe à 0.
2020-04-01 18:49:46.510 Info, Node129, Received Alarm report: type=0, level=0, sensorSrcID=0, type:Burglar event:0, status=255
2020-04-01 18:49:46.571 Info, Node129, Received SensorBinary report: Sensor:75 State=Off
2020-04-01 18:49:46.586 Info, Node129, Received SensorBinary report: Sensor:67 State=Off
Un scénario se lance et envoie l’ordre d’éteindre la lumière
[2020-04-01 18:49:48][SCENARIO] Exécution de la commande [Garage][Lumiere][Eteindre]
Le contrôleur envoie la commande Z-Wave pour éteindre la lumière
2020-04-01 18:49:48.336 Info, Node092, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Level - 0 - 1 -
2020-04-01 18:49:48.336 Info, Node092, SwitchMultilevel::Set - Setting to level 0
2020-04-01 18:49:48.336 Info, Node092, Duration: Default
Mais, il manque encore des lignes, le message n’est donc pas envoyé. Je peux comprendre que le contrôleur ne puisse pas reçevoir entièrement un message, mais pas pour enovoyer.
J’aurais dû avoir quelque chose comme ceci.
Info, Node092, Sending (Send) message (Callback ID=0x65, Expected Reply=0x13) - MultiChannel Encapsulated (instance=1): SwitchMultilevelCmd_Set (Node=92): 0x01, 0x0f, 0x00, 0x13, 0x5c, 0x08, 0x60, 0x0d, 0x01, 0x01, 0x26, 0x01, 0x00, 0xff, 0x25, 0x65, 0x42
Info, Node092, Request RTT 26 Average Request RTT 25
Info, Node092, Sending (Refresh) message (Callback ID=0x66, Expected Reply=0x04) - MultiChannel Encapsulated (instance=1): SwitchMultilevelCmd_Get (Node=92): 0x01, 0x0d, 0x00, 0x13, 0x5c, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x26, 0x02, 0x25, 0x66, 0xb1
Info, Node092, Request RTT 25 Average Request RTT 25
Info, Node092, Response RTT 36 Average Response RTT 36
Info, Node092, Received a MultiChannelEncap from node 92, endpoint 1 for Command Class COMMAND_CLASS_SWITCH_MULTILEVEL
Info, Node092, Received SwitchMultiLevel report: level=0
Info, Node092, Received SwitchMultiLevel report: level=0
Info, Node092, Received SensorMultiLevel report from node 92, instance 1, Power: value=18.4W
Info, Node092, Received SensorMultiLevel report from node 92, instance 1, Power: value=0.0W
Exactement au même instant, à 18:49:48.336, il y a une communication avec le capteur de porte. Là, je comprends qu’il y a un conflit de communication entre les 2 modules qui causent en même temps. Qu’a prévu de faire le protocole Z-Wave dans le cas de communications simultanées ?
2020-04-01 18:49:48.336 Info, NONCES: 0xcd, 0x36, 0xa8, 0x69, 0x8f, 0x17, 0x8d, 0x1a
2020-04-01 18:49:48.336 Info, NONCES: 0x25, 0xda, 0xed, 0x73, 0x56, 0xc7, 0xec, 0xf5
2020-04-01 18:49:48.336 Info, NONCES: 0xb9, 0x57, 0x1c, 0xd4, 0x48, 0x6b, 0xd0, 0xbe
2020-04-01 18:49:48.337 Info, NONCES: 0x11, 0x7c, 0x45, 0x51, 0x36, 0xd6, 0xcb, 0x80
2020-04-01 18:49:48.337 Info, NONCES: 0xad, 0x55, 0x4a, 0xa0, 0xd9, 0x93, 0x86, 0xfd
2020-04-01 18:49:48.337 Info, NONCES: 0x6d, 0x74, 0x71, 0xc4, 0x3b, 0x5d, 0xb9, 0xf4
2020-04-01 18:49:48.337 Info, NONCES: 0x30, 0x30, 0xab, 0x34, 0x9f, 0x19, 0x52, 0x90
2020-04-01 18:49:48.337 Info, NONCES: 0xbf, 0x7b, 0x73, 0x60, 0x8a, 0x4b, 0x31, 0xc9
2020-04-01 18:49:48.337 Info, Node056, Sending (Send) message (Callback ID=0x01, Expected Reply=0x00) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x38, 0x0a, 0x98, 0x80, 0x6d, 0x74, 0x71, 0xc4, 0x3b, 0x5d, 0xb9, 0xf4, 0x05, 0x01, 0x54:
2020-04-01 18:49:48.337 Error, Node056, ERROR: Dropping command, expected response not received after 1 attempt(s)
2020-04-01 18:49:53.069 Info, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
Enfin, c’est l’obtention du fameux Dropping command, expected response not received after 1 attempt(s)
Résultat : la lumière n’a pas pu s’éteindre, la porte est considérée comme toujours ouverte pour Jeedom et le chauffage s’est donc arrêté, 50 min en tout… Et tout ça pour avoir été mettre un truc à la poubelle dans le garage.
J’accepte, depuis peu, que le capteur de porte qui fonctionne en mode sécurisé pourrait poser problème. Mais, je ne comprends pas qu’openzwave ou le contrôleur puisse faire de la merde pareil pour envoyer un ordre.