Analyse du jour : problèmes d’ACK en conséquence des timeout
Maintenant que j’ai de moins en d’erreurs, je vois de plus en plus clair et donc je progresse de plus en plus vite. Je me suis intéressé aux quelques/rares messages suivants :
- Nombre de messages non-sollicités alors qu’en attente d’ACK
- Nombre de ACK retournés en erreur
- Nombre de retours inattendus
Voici le log lors du 1er réveil du module Aeotec Doos Sensor 7 pour lequel je n’ai pas vraiment pu enlever les command class qui ont des souci car elles sont utilisées dans les commandes de l’équipement.
2020-04-24 02:13:16.968 Info, Node099, Received Battery report from node 99: level=100
2020-04-24 02:13:17.014 Info, Node099, Received Wakeup Notification from node 99
2020-04-24 02:13:17.014 Info, Node099, Node 99 has been marked as awake
2020-04-24 02:13:17.018 Info, Deleting all return routes from node 99
2020-04-24 02:13:17.020 Info, Node099, Sending (Command) message (Callback ID=0xf8, Expected Reply=0x47) - ControllerCommand_DeleteAllReturnRoutess (Node=99): 0x01, 0x05, 0x00, 0x47, 0x63, 0xf8, 0x26
2020-04-24 02:13:17.028 Info, Node099, Received reply to FUNC_ID_ZW_DELETE_RETURN_ROUTE - command in progress
2020-04-24 02:13:17.176 Info, Node099, Received Wakeup Notification from node 99
2020-04-24 02:13:17.599 Info, Node099, Received reply to FUNC_ID_ZW_DELETE_RETURN_ROUTE for node 99 - SUCCESS
2020-04-24 02:13:17.601 Info, Assigning return route from node 99 to node 1
2020-04-24 02:13:17.603 Info, Node099, Sending (Command) message (Callback ID=0xf9, Expected Reply=0x46) - ControllerCommand_AssignReturnRoute (Node=99): 0x01, 0x06, 0x00, 0x46, 0x63, 0x01, 0xf9, 0x24
2020-04-24 02:13:17.616 Info, Node099, Received reply to FUNC_ID_ZW_ASSIGN_RETURN_ROUTE - command in progress
2020-04-24 02:13:18.470 Info, Node099, Received reply to FUNC_ID_ZW_ASSIGN_RETURN_ROUTE for node 99 - SUCCESS
2020-04-24 02:13:18.473 Info, Node099, Sending (WakeUp) message (Callback ID=0x15, Expected Reply=0x13) - NoOperation_Set (Node=99): 0x01, 0x09, 0x00, 0x13, 0x63, 0x02, 0x00, 0x00, 0x25, 0x15, 0xb4
2020-04-24 02:13:18.538 Info, Node099, Request RTT 65 Average Request RTT 65
2020-04-24 02:13:18.542 Info, Node099, Number of association groups reported for node 99 is 4.
2020-04-24 02:13:18.543 Info, Node099, Get MultiChannelAssociation for group 1 of node 99
2020-04-24 02:13:18.544 Info, Node099, Sending (Send) message (Callback ID=0xfa, Expected Reply=0x04) - MultiChannelAssociationCmd_Get (Node=99): 0x01, 0x0a, 0x00, 0x13, 0x63, 0x03, 0x8e, 0x02, 0x01, 0x25, 0xfa, 0xd4
2020-04-24 02:13:18.631 Info, Node099, Request RTT 87 Average Request RTT 76
2020-04-24 02:13:18.713 Info, Node099, Response RTT 168 Average Response RTT 168
2020-04-24 02:13:18.713 Info, Node099, Received Multi Instance Association report from node 99, group 1
2020-04-24 02:13:18.713 Info, Node099, The group contains:
2020-04-24 02:13:18.713 Info, Node099, Node 1
2020-04-24 02:13:18.713 Info, Node099, Get MultiChannelAssociation for group 2 of node 99
2020-04-24 02:13:18.713 Info, Node099, Sending (Send) message (Callback ID=0xfb, Expected Reply=0x04) - MultiChannelAssociationCmd_Get (Node=99): 0x01, 0x0a, 0x00, 0x13, 0x63, 0x03, 0x8e, 0x02, 0x02, 0x25, 0xfb, 0xd6
2020-04-24 02:13:18.823 Info, Node099, Request RTT 109 Average Request RTT 92
2020-04-24 02:13:18.902 Info, Node099, Response RTT 188 Average Response RTT 178
2020-04-24 02:13:18.902 Info, Node099, Received Multi Instance Association report from node 99, group 2
2020-04-24 02:13:18.902 Info, Node099, The group contains:
2020-04-24 02:13:18.902 Info, Node099, Get MultiChannelAssociation for group 3 of node 99
2020-04-24 02:13:18.907 Info, Node099, Sending (Send) message (Callback ID=0xfc, Expected Reply=0x04) - MultiChannelAssociationCmd_Get (Node=99): 0x01, 0x0a, 0x00, 0x13, 0x63, 0x03, 0x8e, 0x02, 0x03, 0x25, 0xfc, 0xd0
2020-04-24 02:13:19.012 Info, Node099, Request RTT 106 Average Request RTT 99
2020-04-24 02:13:19.093 Info, Node099, Response RTT 186 Average Response RTT 182
2020-04-24 02:13:19.093 Info, Node099, Received Multi Instance Association report from node 99, group 3
2020-04-24 02:13:19.093 Info, Node099, The group contains:
2020-04-24 02:13:19.093 Info, Node099, Get MultiChannelAssociation for group 4 of node 99
2020-04-24 02:13:19.097 Info, Node099, Sending (Send) message (Callback ID=0xfd, Expected Reply=0x04) - MultiChannelAssociationCmd_Get (Node=99): 0x01, 0x0a, 0x00, 0x13, 0x63, 0x03, 0x8e, 0x02, 0x04, 0x25, 0xfd, 0xd6
2020-04-24 02:13:19.203 Info, Node099, Request RTT 105 Average Request RTT 102
2020-04-24 02:13:19.282 Info, Node099, Response RTT 184 Average Response RTT 183
2020-04-24 02:13:19.282 Info, Node099, Received Multi Instance Association report from node 99, group 4
2020-04-24 02:13:19.282 Info, Node099, The group contains:
2020-04-24 02:13:19.282 Info, Node099, Querying associations for node 99 is complete.
2020-04-24 02:13:19.287 Info, Node099, Sending (Command) message (Callback ID=0x00, Expected Reply=0x80) - Get Routing Info (Node=99): 0x01, 0x07, 0x00, 0x80, 0x63, 0x00, 0x00, 0x03, 0x18
2020-04-24 02:13:19.291 Info, Node099, Received reply to FUNC_ID_ZW_GET_ROUTING_INFO
2020-04-24 02:13:19.292 Info, Node099, Neighbors of this node are:
2020-04-24 02:13:19.292 Info, Node099, Node 1
2020-04-24 02:13:19.292 Info, Node099, Node 45
2020-04-24 02:13:19.292 Info, Node099, Node 48
2020-04-24 02:13:19.292 Info, Node099, Node 76
2020-04-24 02:13:19.292 Info, Node099, Node 78
2020-04-24 02:13:19.292 Info, Node099, Node 82
2020-04-24 02:13:19.292 Info, Node099, Node 89
2020-04-24 02:13:19.292 Info, Node099, Node 92
2020-04-24 02:13:19.292 Info, Node099, Node 97
2020-04-24 02:13:19.293 Info, Node099, CentralScene RequestState: 2
2020-04-24 02:13:19.293 Info, Node099, CentralScene: Not a StaticRequest
2020-04-24 02:13:19.293 Info, Node099, Sending (Query) message (Callback ID=0xfe, Expected Reply=0x04) - PowerlevelCmd_Get (Node=99): 0x01, 0x09, 0x00, 0x13, 0x63, 0x02, 0x73, 0x02, 0x25, 0xfe, 0x2e
2020-04-24 02:13:19.392 Info, Node099, Request RTT 98 Average Request RTT 100
2020-04-24 02:13:19.472 Info, Node099, Response RTT 178 Average Response RTT 180
2020-04-24 02:13:19.472 Info, Node099, Received a PowerLevel report: PowerLevel=Normal, Timeout=0
2020-04-24 02:13:19.475 Info, Node099, Sending (Query) message (Callback ID=0xff, Expected Reply=0x04) - WakeUpCmd_IntervalGet (Node=99): 0x01, 0x09, 0x00, 0x13, 0x63, 0x02, 0x84, 0x05, 0x25, 0xff, 0xdf
2020-04-24 02:13:19.582 Info, Node099, Request RTT 107 Average Request RTT 103
2020-04-24 02:13:19.663 Info, Node099, Response RTT 187 Average Response RTT 183
2020-04-24 02:13:19.663 Info, Node099, Received Wakeup Interval report from node 99: Interval=21600, Target Node=1
2020-04-24 02:13:19.665 Info, Node099, CentralScene RequestState: 4
2020-04-24 02:13:19.665 Info, Node099, CentralScene: Not a StaticRequest
2020-04-24 02:13:19.666 Info, Node099, Sending (Send) message (Callback ID=0x0a, Expected Reply=0x04) - BasicCmd_Get (Node=99): 0x01, 0x09, 0x00, 0x13, 0x63, 0x02, 0x20, 0x02, 0x25, 0x0a, 0x89
2020-04-24 02:13:19.770 Info, Node099, Request RTT 103 Average Request RTT 103
2020-04-24 02:13:27.666 Error, Node099, ERROR: Dropping command, expected response not received after 1 attempt(s)
2020-04-24 02:13:27.669 Info, Node099, Sending (Send) message (Callback ID=0x0b, Expected Reply=0x04) - SensorBinaryCmd_Get (Node=99): 0x01, 0x09, 0x00, 0x13, 0x63, 0x02, 0x30, 0x02, 0x25, 0x0b, 0x98
2020-04-24 02:13:27.720 Info, Node099, Request RTT 50 Average Request RTT 76
2020-04-24 02:13:35.669 Error, Node099, ERROR: Dropping command, expected response not received after 1 attempt(s)
2020-04-24 02:13:35.673 Info, Node099, Sending (Send) message (Callback ID=0x0c, Expected Reply=0x04) - AlarmCmd_Get (Node=99): 0x01, 0x0c, 0x00, 0x13, 0x63, 0x05, 0x71, 0x04, 0x00, 0x00, 0x01, 0x25, 0x0c, 0xdb
2020-04-24 02:13:43.673 Error, Node099, ERROR: Dropping command, expected response not received after 1 attempt(s)
2020-04-24 02:13:43.676 Info, Node099, Sending (Send) message (Callback ID=0x0d, Expected Reply=0x04) - AlarmCmd_Get (Node=99): 0x01, 0x0c, 0x00, 0x13, 0x63, 0x05, 0x71, 0x04, 0x00, 0x06, 0x01, 0x25, 0x0d, 0xdc
2020-04-24 02:13:45.666 Info, Node099, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
2020-04-24 02:13:45.666 Info, Node099, Node 99 has been marked as asleep
2020-04-24 02:13:45.667 Info, Node099, Node not responding - moving message to Wake-Up queue: AlarmCmd_Get (Node=99): 0x01, 0x0c, 0x00, 0x13, 0x63, 0x05, 0x71, 0x04, 0x00, 0x06, 0x01, 0x25, 0x0d, 0xdc
2020-04-24 02:13:45.667 Info, Node099, Node not responding - moving message to Wake-Up queue: AlarmCmd_Get (Node=99): 0x01, 0x0c, 0x00, 0x13, 0x63, 0x05, 0x71, 0x04, 0x00, 0x07, 0x01, 0x25, 0x0e, 0xde
2020-04-24 02:13:45.667 Info, Node099, Node not responding - moving message to Wake-Up queue: BatteryCmd_Get (Node=99): 0x01, 0x09, 0x00, 0x13, 0x63, 0x02, 0x80, 0x02, 0x25, 0x0f, 0x2c
2020-04-24 02:13:45.667 Info, Node099, Node not responding - moving QueryStageComplete command to Wake-Up queue
2020-04-24 02:13:51.467 Warning, WARNING: Unexpected Callback ID received
Lors du réveil, les 3 commandes mal supportées BasicCmd_Get SensorBinaryCmd_Get et AlarmCmd_Get font perdre ici beaucoup trop de temps (3x8=24 secondes). La conséquence est que le module se rendort avant la fin de l’interview et donc on se reprend des warning supplémentaires du style
Node099, WARNING: ZW_SEND_DATA failed. No ACK received - device may be asleep.
Warning, WARNING: Unexpected Callback ID received
Il faudra donc attendre le prochain réveil pour terminer l’interview.
Ainsi le %OK ne peut pas commencer à 100% lors du 1er réveil (moi qui cherche du 100% vert)
L’interview devrait pouvoir se terminer entièrement du premier coup.
D’où l’intéret de ne pas avoir ces commandes non supportées.
C’est pire en sécurisé car les communication sont plus longues.
EDIT: J’ai modifié le fichier config zwa008.xml pour virer la classe COMMAND_CLASS_BASIC, ainsi l’erreur avec le BasicCmd_Get a disparu.
De plus, j’avais 3 modules identiques dont 1 qui n’avait pas de problème avec SensorBinaryCmd_Get. Un espoir ! En fait, c’était dû à l’inclusionen faite en mode sécurisé (ce module gère le niveau S2) alors que le module fonctionnait pourtant en non sécurisé (je n’avais pas de cadenas quelque soit le mode d’inclusion). L’inclusion normale m’a fait disparaitre l’erreur SensorBinaryCmd_Get. Ainsi, je ne perds pas la fonction Tilt de ce module et il ne me reste plus que l’erreur avec AlarmCmd_Get. Par conséquent, en évitant 2 timeouts, je n’ai plus le problème d’ACK que je viens d’expliquer dans ce post. 