Soucis sur mon réseau z-wave

[mich0111]

Il y a longtemps que j’ai arrêté d’essayer le mode sécurisé.
Quand je vois le nombre de sujets disant qu’il n’y a pas de problème avec, je me dis que soit je m’y prends mal, soit je n’ai pas de chance.
Quoiqu’il en soit, je n’ai quasiment pas de problème comme ça.

[Domatizer]

@mich0111

Quand je vois le nombre de sujets disant qu’il n’y a pas de problème avec, je me dis que soit je m’y prends mal, soit je n’ai pas de chance

Oui, c’est juste de la malchance qui arrive d’autant plus souvent que le nombre de modules sécurisés en grand ! Même si tu t’y prends bien.

Une collision peut arriver, mais pourquoi openzwave qui n’a pas reçu l’accusé de réception ne refait pas une tentative d’envoi ?

[mich0111]

@Domatizer

Oui, c’est juste de la malchance

Comme je l’écrivais, j’ai laissé tombé le mode sécurisé. Aucun de mes modules n’ait inclus de cette façon.
Du coup, plus de problème et plus de malchance.

[Bison]

Mais ces collisions ne vous paralyses pas le zwave avec surcharge cpu n’est ce pas ?

[Mips]

Pourquoi je devrais « prouver »…
Ça m’avancerait à quoi de dire que toutes mes modules sont en sécurisé et que je n’ai pas de problème ?
Je ne travaille pas pour « zwave sécurité »

[Domatizer]

@Bison

Mais ces collisions ne vous paralyses pas le zwave avec surcharge cpu n’est ce pas ?

Non, c’est juste un ordre mal envoyé parmi d’autres, de la malchance ! Et il n’y a pas de tentative de renvoi. Pourtant il me semblait que le Z-Wave faisait 3 tentatives avant de statuer un échec…

Sinon, la queue sortante peut se bloquer lorsque j’effectue des actions sur le réseau ou des nœuds. Souvent, lorsque j’enchaîne les exclusions/inclusions, la queue sortante fini par se bloquer, impossible donc de continuer à faire des exclusions/inclusions sans redémarrer le daemon. Si j’envoie des ordres entre temps, la queue sortante monte mais ne redescend pas, mais le contrôleur continu à recevoir les infos des capteurs, donc les scenarii tournent et lancent des actions, ainsi la queue continue de monter de plus en plus haut…
Mais le réseau Z-Wave ne plante plus de lui-même. J’ai eu ce problème au début en décembre dernier lorsque je ne fixais pas les ports USB. La clé GSM se déconnecte souvent et se reconnecte sur le port suivant. Résultat, la plupart des dongles USB se mettaient en vrac tous 2 ou 3 jours. Solution ici Changement inopiné port USB clé ZWave - #9 par Domatizer Le problème n’est pas 100% résolu pour certains protocoles, mais ce n’est plus bloquant.

[Domatizer]

@Mips

Pourquoi je devrais « prouver »…
Ça m’avancerait à quoi de dire que toutes mes modules sont en sécurisé et que je n’ai pas de problème ?

Pour démontrer l’inverse par exemple, que le sécurisé marche super bien avec openzwave. Cela intéressera certainement les galériens (malchanceux) du Z-Wave. Peut-être que je me trompe dans tous mes raisonnements ? Je cherche une solution pour faire fonctionner correctement le réseau Z-Wave et comprendre pourquoi il ne marche pas bien actuellement.

[leon-99]

Bonjour
Je suis la discution avec interet et j’aurais une remarque a faire: je me rappelle avoir lu en quelque part dans les blogs et tuto de Nechry que les reseaux securisés et non securisés etaient indépendant l’un de l’autre, donc ca revenait a gerer 2 reseaux avec les problemes de distance. de voisinage pile ou secteur etc…
A confirmer ??

[Madcow]

Bonjour,

C’est inexact justement selon Nechry.
Voir réponse de @Mav3656 dans ce même fil.

Soucis sur mon réseau z-wave

Bonjour, @Mips a raison, il faut attendre de visualiser le temps qu’a mis le réseau à démarrer dans l’écran « réseau Zwave → résumé » avant toute chose. Un réseau correctement configuré doit démarrer rapidement, quelques minutes max. En théorie, cela devrait démarrer en quelques secondes, mais à cause des nombreux messages non gérés par la librairie openzwave, on a énormément de timeout. En fait, chaque fois que vous avez le temps de visualiser la queue du contrôleur figée sur un nombre donné…

[leon-99]

Ok merci pour le lien… j’avais pas tout lu chez Nechry

[Domatizer]

Maintenant que mon réseau fonctionne à plus de 99% du temps. C’est plus facile pour analyser le 1% restant.

Avant que je passe tout le reste des modules en non sécurisé, voici encore un exemple de malchance

• 1 Fibaro Dimmer 2 en sécurisé (Node054)
• 1 Fibaro Motion Sensor 2 en sécurisé (Node052)

Je quitte la pièce en éteignant manuellement la lumière à l’interrupteur et en ouvrant la porte qui était fermée dans la même fraction de seconde. En réalité, l’extinction de la lumière (Node054) a bien été prise en compte mais pas l’ouverture de porte (Node052).

2020-04-12 12:36:08.905 Info, Node054, Received SecurityCmd_NonceGet from node 54
2020-04-12 12:36:08.905 Info, NONCES: 0xb6, 0xcf, 0x9a, 0x0d, 0xe0, 0xd4, 0xe0, 0xe4
2020-04-12 12:36:08.905 Info, NONCES: 0x32, 0x53, 0xf7, 0xec, 0x5f, 0xd3, 0x09, 0x15
2020-04-12 12:36:08.905 Info, NONCES: 0xa3, 0xa3, 0x23, 0x84, 0x77, 0x04, 0x68, 0x30
2020-04-12 12:36:08.906 Info, NONCES: 0x02, 0xcc, 0xfb, 0x2a, 0x76, 0xea, 0x36, 0xa7
2020-04-12 12:36:08.906 Info, NONCES: 0xac, 0x39, 0xbf, 0x50, 0x16, 0x62, 0x3e, 0x3d
2020-04-12 12:36:08.906 Info, NONCES: 0xae, 0xc5, 0xa5, 0x14, 0x07, 0x33, 0xa7, 0xf0
2020-04-12 12:36:08.906 Info, NONCES: 0x62, 0xaa, 0xf3, 0x7d, 0x57, 0x11, 0x39, 0xd2
2020-04-12 12:36:08.906 Info, NONCES: 0xe3, 0x87, 0x64, 0xeb, 0xba, 0x0c, 0xdc, 0x1c
2020-04-12 12:36:08.906 Info, Node054, Sending (Refresh) message (Callback ID=0x01, Expected Reply=0x00) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x36, 0x0a, 0x98, 0x80, 0x02, 0xcc, 0xfb, 0x2a, 0x76, 0xea, 0x36, 0xa7, 0x05, 0x01, 0xcf:
2020-04-12 12:36:08.940 Info, Node052, Received SecurityCmd_NonceGet from node 52
2020-04-12 12:36:08.941 Info, NONCES: 0x24, 0xd4, 0x92, 0x76, 0xf4, 0xc5, 0x68, 0xc4
2020-04-12 12:36:08.941 Info, NONCES: 0x48, 0xa5, 0xcc, 0xde, 0x62, 0xf7, 0x03, 0x5e
2020-04-12 12:36:08.941 Info, NONCES: 0x3d, 0x2e, 0x94, 0x9c, 0x01, 0x9d, 0xb1, 0xa5
2020-04-12 12:36:08.941 Info, NONCES: 0x4f, 0x73, 0xed, 0xd6, 0xad, 0x76, 0xcb, 0x32
2020-04-12 12:36:08.941 Info, NONCES: 0x01, 0xa4, 0x8f, 0x4e, 0xb9, 0x77, 0xeb, 0x42
2020-04-12 12:36:08.941 Info, NONCES: 0x5d, 0xc0, 0x58, 0x5a, 0xf1, 0x81, 0x85, 0xbd
2020-04-12 12:36:08.941 Info, NONCES: 0xef, 0x68, 0xae, 0xa7, 0xb4, 0x8a, 0x67, 0x7b
2020-04-12 12:36:08.941 Info, NONCES: 0x74, 0x13, 0x05, 0xe5, 0xb6, 0x7d, 0x0d, 0xf5
2020-04-12 12:36:08.941 Info, Node052, Sending (Refresh) message (Callback ID=0x01, Expected Reply=0x00) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x34, 0x0a, 0x98, 0x80, 0x3d, 0x2e, 0x94, 0x9c, 0x01, 0x9d, 0xb1, 0xa5, 0x05, 0x01, 0x4c:
2020-04-12 12:36:08.948 Info, Node054, Received SecurityCmd_NonceGet from node 54
2020-04-12 12:36:08.948 Info, NONCES: 0xb6, 0xcf, 0x9a, 0x0d, 0xe0, 0xd4, 0xe0, 0xe4
2020-04-12 12:36:08.948 Info, NONCES: 0x32, 0x53, 0xf7, 0xec, 0x5f, 0xd3, 0x09, 0x15
2020-04-12 12:36:08.948 Info, NONCES: 0xa3, 0xa3, 0x23, 0x84, 0x77, 0x04, 0x68, 0x30
2020-04-12 12:36:08.948 Info, NONCES: 0x02, 0xcc, 0xfb, 0x2a, 0x76, 0xea, 0x36, 0xa7
2020-04-12 12:36:08.948 Info, NONCES: 0x41, 0xd5, 0x29, 0xb8, 0xd9, 0x91, 0xe8, 0x20
2020-04-12 12:36:08.949 Info, NONCES: 0xae, 0xc5, 0xa5, 0x14, 0x07, 0x33, 0xa7, 0xf0
2020-04-12 12:36:08.949 Info, NONCES: 0x62, 0xaa, 0xf3, 0x7d, 0x57, 0x11, 0x39, 0xd2
2020-04-12 12:36:08.949 Info, NONCES: 0xe3, 0x87, 0x64, 0xeb, 0xba, 0x0c, 0xdc, 0x1c
2020-04-12 12:36:08.949 Info, Node054, Sending (Refresh) message (Callback ID=0x01, Expected Reply=0x00) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x36, 0x0a, 0x98, 0x80, 0x41, 0xd5, 0x29, 0xb8, 0xd9, 0x91, 0xe8, 0x20, 0x05, 0x01, 0x58:
2020-04-12 12:36:08.949 Warning, m_currentMsg was NULL when trying to set MaxSendAttempts
2020-04-12 12:36:08.949 Always,
2020-04-12 12:36:08.949 Always, Dumping queued log messages
2020-04-12 12:36:08.949 Always,
2020-04-12 12:36:08.950 Always,
2020-04-12 12:36:08.950 Always, End of queued log message dump
2020-04-12 12:36:08.950 Always,
2020-04-12 12:36:08.954 Error, ERROR: ZW_SEND_DATA could not be delivered to Z-Wave stack

Dans le log, on voit bien que les 2 modules ont communiqué, pas de problème de portée (ceux ne sont pas les modules qui déconnent, surtout Fibaro, ils en vendent des millions, sinon ça se saurait). Puis ça ch*e dans la colle. Que veut dire cette partie ?

2020-04-12 12:36:08.949 Warning, m_currentMsg was NULL when trying to set MaxSendAttempts
2020-04-12 12:36:08.949 Always,
2020-04-12 12:36:08.949 Always, Dumping queued log messages
2020-04-12 12:36:08.949 Always,
2020-04-12 12:36:08.950 Always,
2020-04-12 12:36:08.950 Always, End of queued log message dump
2020-04-12 12:36:08.950 Always,

Alors, pour éviter les collisions, j’ai la solution : j’ouvre la porte, j’attends 2 secondes que le détection soit envoyée, j’allume la lumière à l’interrupteur, j’attends 2 secondes que l’info soit remontée, j’entre dans la pièce, j’attends 2 secondes que la détection soit envoyée et je pourrais enfin dire que ça marche en sécurisé. Et si ce n’est pas satisfaisant, j’impose un confinement strict des personnes dans leurs pièces, c’est à cause d’eux que la domotique déraille, car je vois déjà bien l’amélioration la nuit lors du couvre-feu. Non, je déconne, c’est à la domotique de s’adapter.

[mich0111]

J’ai adoré ton séquencement.
Je vais réfléchir à imposer les mêmes règles chez moi.

[Mav3656]

Bonjour @Domatizer,
T’est-il possible de fournir des logs en debug de ce problème de « collision » ? Peux-tu rappeler ton architecture matériel et contrôleur Zwave utilisé stp ?

(Je te conseille d’avoir un bon historique 5000 ou 10000 lignes car en debug le zwave a beaucoup de chose à dire, sauf si tu peux récupérer le log immédiatement)

@Bison As-tu essayé de changer de port USB physiquement sur le QNAP ? Le problème est-il toujours présent de la même manière ?

Si tu en as la possibilité un jour, ton test serait intéressant à reproduire sur ton QNAP et ton PC avec un autre contrôleur ZWave (un modèle utilisé par le + grand nombre si possible), pour écarter la piste d’un matériel défectueux ou d’un comportement spécifique mal ou non géré par la Openzwave avec ta clé Vision.

Retour d’expérience : sur SMART, je n’ai jamais eu « queue bloqué + CPU à 100% » en soignant le réseau via l’interface web Jeedom. En revanche j’ai ce symptôme en utilisant l’API REST du plugin via un script. Le script appelle la commande « noeud en échec » sur l’ensemble de mes modules FLiRS/secteurs et peut marcher des dizaines de fois puis sans prévenir produit ce phénomène.

Bonne journée,
Pierre (Mav3656) - Helper Officiel Jeedom.

[Bison]

@Mav3656, je vais surement passer à la phase "commande d’une Aeotec ZW090 GEN5 comme ça on sera effectivement fixé pour vérifier si le comportement est le même !

[Domatizer]

@Mav3656

T’est-il possible de fournir des logs en debug de ce problème de « collision » ? Peux-tu rappeler ton architecture matériel et contrôleur Zwave utilisé stp ?

(Je te conseille d’avoir un bon historique 5000 ou 10000 lignes car en debug le zwave a beaucoup de chose à dire, sauf si tu peux récupérer le log immédiatement)

Je suis en Info avec déjà 10000 lignes, j’ai environ 5 et 10 lignes d’erreur pour les 10 dernières d’heures en journée. Le fichier de log a déjà tendance à planter lorsqu’il atteint les 10MB, je perds tout le contenu d’un coup. En debug, l’historique ne sera pas très long, il faudrait mettre 1 million de lignes. Je vais essayer… Est-t-il possible d’avoir 1 million de lignes uniquement pour le plugin openzwave et non pas tous les plugins ?

Pour rappel, j’ai la config suivante

• Jeedom 4.0.49 (1900 commandes, 260 équipements, environ 150 scenarii)
• Raspberry Pi 3b+ (Alim 2.5A)
• Hub USB 2.0 7 Ports DLink DUB-H7 alimenté avec une alim 3A
• Clé 1-Wire Dallas Semiconductor DS9490R (sondes DS18B20) (+alim 5V pour le réseau 1-Wire)
• Clé Aeotec Z-Stick Gen 5 ZW090 (modules uniquement Z-Wave+)
• Clé 3G Huawei E3531 HSPA+
• Clé ZiBlue RF Player 1000 (sondes Oregon + prises Chacon)
• Pas de Bluetooth (le Bluetooth interne n’est pas désactivé comme il faut le faire pour le razberry)

La clé Aeotec Z-Stick Gen 5 est branchée directement sur le Raspberry, tous les autres dongles sont sur le Hub.

[Mav3656]

@Domatizer

Est-t-il possible d’avoir 1 million de lignes uniquement pour le plugin openzwave et non pas tous les plugins ?

Malheureusement pas possible de spécifier un nombre de lignes /plugin. Je n’ai pas essayé au-delà de 10 000 lignes. Ça ne me semble pas être une bonne idée de mettre 1 million… peut-être 20 ou 30 mille lignes. 50 mille éventuellement ? Tu peux faire des essais…

Quoi qu’il en soit il faudra récupérer les logs plus ou moins rapidement selon historique.

Cdt.,
Pierre (Mav3656) - Helper Officiel Jeedom.

[Domatizer]

@Mav3656

Quoi qu’il en soit il faudra récupérer les logs plus ou moins rapidement selon historique.

Il me faudrait un script qui sauvegarde le log régulièrement, ainsi, j’aurais tout l’historique mais avec des périodes en double. Je vais voir ce que je peux faire…

[Domatizer]

@Mav3656

En mode Debug, le log se remplie trop vite, je suis avec 20000 lignes, je ne peux même pas avoir le démarrage du réseau en entier.
En parallèle, j’ai un script qui me sauvegarde les fichiers openzwave et openzwaved toutes les heures.
Je vais bien réussir à attraper quelque chose…

Pour l’instant pas de collision, mais j’ai déjà un module Fibaro Dimmer 2 sécurisé qui a eu un problème tout seul lorsqu’un scénario a allumé la lumière. Ici, la lumière s’est bien allumée donc rien de grave.

2020-04-12 22:08:13.548 Detail, Node050,   Received: 0x01, 0x08, 0x00, 0x04, 0x00, 0x32, 0x02, 0x98, 0x40, 0x1b
2020-04-12 22:08:13.548 Info, Node050, Received SecurityCmd_NonceGet from node 50
2020-04-12 22:08:13.548 Info, NONCES: 0x65, 0xd9, 0x43, 0x33, 0xc5, 0xbb, 0x09, 0x0b
2020-04-12 22:08:13.548 Info, NONCES: 0xb6, 0xf9, 0x1f, 0x21, 0xdd, 0x4a, 0x4b, 0x4b
2020-04-12 22:08:13.548 Info, NONCES: 0xb3, 0x8a, 0x68, 0xd2, 0x93, 0xeb, 0x38, 0xca
2020-04-12 22:08:13.548 Info, NONCES: 0xd5, 0xb6, 0xa2, 0x84, 0x9f, 0x80, 0x94, 0xab
2020-04-12 22:08:13.548 Info, NONCES: 0x45, 0x33, 0x49, 0xa8, 0xf2, 0x38, 0x81, 0xc7
2020-04-12 22:08:13.548 Info, NONCES: 0xa1, 0xd5, 0xd0, 0xc5, 0x07, 0x97, 0x9e, 0xc3
2020-04-12 22:08:13.548 Info, NONCES: 0x61, 0xa5, 0x19, 0x53, 0xde, 0x9b, 0x1a, 0xce
2020-04-12 22:08:13.548 Info, NONCES: 0x82, 0x63, 0x88, 0xcc, 0x62, 0xa5, 0xcb, 0x49
2020-04-12 22:08:13.548 Info, Node050, Sending (Refresh) message (Callback ID=0x01, Expected Reply=0x00) - Nonce_Report - 0x01, 0x11, 0x00, 0x13, 0x32, 0x0a, 0x98, 0x80, 0xb6, 0xf9, 0x1f, 0x21, 0xdd, 0x4a, 0x4b, 0x4b, 0x05, 0x01, 0x3f:
2020-04-12 22:08:13.551 Detail,   Received: 0x01, 0x04, 0x01, 0x13, 0x00, 0xe9
2020-04-12 22:08:13.551 Error, ERROR: ZW_SEND_DATA could not be delivered to Z-Wave stack

Les log complets du Node050 pour cette communication
openzwaved_Debug_Node050.log (12,9 Ko)
openzwave_Debug_Node050.log (11,2 Ko)
Je ne sais pas quoi conclure ici.

Sinon, au démarrage, comme je l’avais déjà fait remarquer dans mes premiers posts, les modules remontent souvent une erreur avec la commande AlarmCmd_Get lors de leur réveil, peut-être une commande mal supportée ?

2020-04-12 22:51:57.534 Info, Node056, Processing (Send) Nonce Request message (Callback ID=0xfe, Expected Reply=0x04)
2020-04-12 22:51:57.534 Info, Node056, Sending (Send) message (Callback ID=0x02, Expected Reply=0x04) - Nonce_Get(AlarmCmd_Get) - 0x01, 0x09, 0x00, 0x13, 0x38, 0x02, 0x98, 0x40, 0x05, 0x02:
2020-04-12 22:51:57.543 Detail, Node056,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-04-12 22:51:57.543 Detail, Node056,   ZW_SEND_DATA delivered to Z-Wave stack
2020-04-12 22:51:57.653 Detail, Node056,   Received: 0x01, 0x07, 0x00, 0x13, 0x02, 0x00, 0x00, 0x0b, 0xe2
2020-04-12 22:51:57.653 Detail, Node056,   ZW_SEND_DATA Request with callback ID 0x02 received (expected 0x02)
2020-04-12 22:51:57.653 Info, Node056, Request RTT 118 Average Request RTT 116
2020-04-12 22:51:57.725 Detail, Node056,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x38, 0x0a, 0x98, 0x80, 0x35, 0xd4, 0x49, 0x4c, 0xcf, 0x2c, 0xa9, 0x56, 0x39
2020-04-12 22:51:57.725 Info, Node056, Received SecurityCmd_NonceReport from node 56
2020-04-12 22:51:57.725 Info, Node056, Sending (Send) message (Callback ID=0x0e, Expected Reply=0x04) - AlarmCmd_Get (Node=56): 0x01, 0x0c, 0x00, 0x13, 0x38, 0x05, 0x71, 0x04, 0x00, 0x00, 0x01, 0x25, 0x0e, 0x82
2020-04-12 22:51:57.737 Detail, Node056,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-04-12 22:51:57.737 Detail, Node056,   ZW_SEND_DATA delivered to Z-Wave stack
2020-04-12 22:51:57.857 Detail, Node056,   Received: 0x01, 0x07, 0x00, 0x13, 0x0e, 0x00, 0x00, 0x0d, 0xe8
2020-04-12 22:51:57.857 Detail, Node056,   ZW_SEND_DATA Request with callback ID 0x0e received (expected 0x0e)
2020-04-12 22:51:57.857 Info, Node056, Request RTT 322 Average Request RTT 219
2020-04-12 22:51:57.857 Detail,   Expected callbackId was received
2020-04-12 22:52:01.535 Error, Node056, ERROR: Dropping command, expected response not received after 1 attempt(s)
2020-04-12 22:52:01.535 Detail, Node056, Removing current message
2020-04-12 22:52:01.535 Detail, Node056, Notification: Notification - TimeOut
2020-04-12 22:52:01.543 Detail,
2020-04-12 22:52:01.543 Info, Node056, Processing (Send) Nonce Request message (Callback ID=0xff, Expected Reply=0x04)
2020-04-12 22:52:01.544 Info, Node056, Sending (Send) message (Callback ID=0x02, Expected Reply=0x04) - Nonce_Get(AlarmCmd_Get) - 0x01, 0x09, 0x00, 0x13, 0x38, 0x02, 0x98, 0x40, 0x05, 0x02:
2020-04-12 22:52:01.552 Detail, Node056,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-04-12 22:52:01.552 Detail, Node056,   ZW_SEND_DATA delivered to Z-Wave stack
2020-04-12 22:52:01.616 Detail, Node056,   Received: 0x01, 0x07, 0x00, 0x13, 0x02, 0x00, 0x00, 0x07, 0xee
2020-04-12 22:52:01.616 Detail, Node056,   ZW_SEND_DATA Request with callback ID 0x02 received (expected 0x02)
2020-04-12 22:52:01.616 Info, Node056, Request RTT 72 Average Request RTT 145

À suivre…

[Mav3656]

@Domatizer

Pour l’instant pas de collision, mais j’ai déjà un module Fibaro Dimmer 2 sécurisé qui a eu un problème tout seul lorsqu’un scénario a allumé la lumière. Ici, la lumière s’est bien allumée donc rien de grave.

@Domatizer Ce que je comprends de la séquence (à partir du fichier openzwaved_Debug_Node050.log) :

Use case : tu allumes la lumière à partir de Jeedom (pas à partir d’un interrupteur).

Pré-requis : pour une commande sécurisée entre 2 interlocuteurs A et B :

• Il y a une clé de communication tournante. Comprendre que ce n’est jamais la même clé qui va chiffrer un message contenant de la data.
• Celui qui est à l’initiative de la communication (celui qui a une information à transmettre) (« A » par exemple) demande à l’autre (« B » pour nous ici) de lui donner l’index de la clé à utiliser pour s’accorder sur la communication à venir (message "Nonce_Get).
• B indique qu’il a bien reçu le message (accusé réception)
• B répond avec l’index à utiliser (message « Nonce_Report »)
• A indique qu’il a bien reçu le message (accusé réception)
• A ce moment là, A va pouvoir dire ce qu’il a à dire, en chiffrant la communication
• B indique qu’il a bien reçu le message (accusé réception)
• Dans notre cas, la communication prend fin ici.

On visualise ici le traffic supplémentaire que génère les messages échangés pour obtenir les « NONCES » - là où un traffic non sécurisé ne ferait qu’émettre son message. Toutefois, les logs mettent en évidence la vitesse à laquelle s’effectue ces échangent - peu ou pas perceptible à l’échelle humaine.

Les plus observateurs auront sans doute observé que pour un module donné, une seule ligne change lorsque les NONCES sont affichés dans les logs. Il s’agit de celle utilisée. Les autres lignes ne sont qu’un historique tournant, pour rappel des dernières NONCES utilisées.

Ce qui s'est passé (selon moi)

Jeedom souhaite émettre un message spontanément au module 050 pour lui demander de s’allumer. On voit qu’il prévoit également dans la foulée de ne pas faire confiance au module pour remonter spontanément son changement d’état, et prévoit de lui demander sa nouvelle valeur (quand on cherche du traffic inutile, je pense que ce traffic généré est plus inutile que celui lié à la sécurité du réseau ).

Dans le meilleur des cas, on recevra l’information en double (car le module doit émettre son changement d’état), et dans le pire des cas, cela peut être source de bug si le module n’est pas encore retombé sur ses pied et envoie une ancienne valeur lorsque Jeedom lui demandera immédiatement d’envoyer son état.

On voit ces éléments au début de ton fichier lignes 4 à 7

2020-04-12 22:08:12.935 Info, Node050, Value::Set - COMMAND_CLASS_SWITCH_MULTILEVEL - Level - 0 - 1 - ?
2020-04-12 22:08:12.935 Info, Node050, SwitchMultilevel::Set - Setting to level 255
2020-04-12 22:08:12.935 Info, Node050,   Duration: Default
2020-04-12 22:08:12.935 Detail, Node050, Setting Encryption Flag on Message For Command Class COMMAND_CLASS_MULTI_INSTANCE/CHANNEL
2020-04-12 22:08:12.935 Detail, Node050, Queuing (Send) MultiChannel Encapsulated (instance=1): SwitchMultilevelCmd_Set (Node=50): 0x01, 0x0f, 0x00, 0x13, 0x32, 0x08, 0x60, 0x0d, 0x01, 0x01, 0x26, 0x01, 0xff, 0xff, 0x25, 0x49, 0xff
2020-04-12 22:08:12.935 Detail, Node050, Setting Encryption Flag on Message For Command Class COMMAND_CLASS_MULTI_INSTANCE/CHANNEL
2020-04-12 22:08:12.935 Detail, Node050, Queuing (Refresh) MultiChannel Encapsulated (instance=1): SwitchMultilevelCmd_Get (Node=50): 0x01, 0x0d, 0x00, 0x13, 0x32, 0x06, 0x60, 0x0d, 0x01, 0x01, 0x26, 0x02, 0x25, 0x4a, 0xf3

Ensuite ? Et bien il y a 2 messages dans la QUEUE, c’est parti !

2020-04-12 22:08:12.936 Info, Node050, Processing (Send) Nonce Request message (Callback ID=0x49, Expected Reply=0x13)

1er message à envoyer, l’ordre de changement d’état au module. On reprend le paragraphe pré-requis, on voit que Jeedom (initiateur de la communication, représente le module « A ») et on applique l’algorithme :

• Jeedom émet un Nonce_Get

2020-04-12 22:08:12.936 Info, Node050, Sending (Send) message (Callback ID=0x02, Expected Reply=0x13) - Nonce_Get(MultiChannel Encapsulated (instance=1): SwitchMultilevelCmd_Set) - 0x01, 0x09, 0x00, 0x13, 0x32, 0x02, 0x98, 0x40, 0x05, 0x02:

• 050 émet un accusé réception

2020-04-12 22:08:12.943 Detail, Node050,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-04-12 22:08:12.943 Detail, Node050,   ZW_SEND_DATA delivered to Z-Wave stack
2020-04-12 22:08:12.959 Detail, Node050,   Received: 0x01, 0x07, 0x00, 0x13, 0x02, 0x00, 0x00, 0x02, 0xeb
2020-04-12 22:08:12.960 Detail, Node050,   ZW_SEND_DATA Request with callback ID 0x02 received (expected 0x02)
2020-04-12 22:08:12.960 Info, Node050, Request RTT 23 Average Request RTT 53

• 050 émet un Nonce_Report

2020-04-12 22:08:12.972 Detail, Node050,   Received: 0x01, 0x10, 0x00, 0x04, 0x00, 0x32, 0x0a, 0x98, 0x80, 0x2f, 0x64, 0x7f, 0x6e, 0xe3, 0xb0, 0x39, 0xcc, 0x37
2020-04-12 22:08:12.972 Info, Node050, Received SecurityCmd_NonceReport from node 50

• Jeedom émet un accusé réception (on ne le voit pas dans les logs)
• Jeedom envoie la commande de manière chiffrée pour dire au module de s’allumer

2020-04-12 22:08:12.973 Info, Node050, Sending (Send) message (Callback ID=0x4b, Expected Reply=0x13) - MultiChannel Encapsulated (instance=1): SwitchMultilevelCmd_Set (Node=50): 0x01, 0x0f, 0x00, 0x13, 0x32, 0x08, 0x60, 0x0d, 0x01, 0x01, 0x26, 0x01, 0xff, 0xff, 0x25, 0x4b, 0xfd

• 050 émet un accusé réception

2020-04-12 22:08:12.984 Detail, Node050,   Received: 0x01, 0x04, 0x01, 0x13, 0x01, 0xe8
2020-04-12 22:08:12.984 Detail, Node050,   ZW_SEND_DATA delivered to Z-Wave stack
2020-04-12 22:08:13.002 Detail, Node050,   Received: 0x01, 0x07, 0x00, 0x13, 0x4b, 0x00, 0x00, 0x03, 0xa3
2020-04-12 22:08:13.002 Detail, Node050,   ZW_SEND_DATA Request with callback ID 0x4b received (expected 0x4b)

• Jeedom clôt cette étape d’envoi du premier message mis en QUEUE

2020-04-12 22:08:13.002 Detail,   Expected callbackId was received
2020-04-12 22:08:13.002 Detail,   Expected reply was received
2020-04-12 22:08:13.002 Detail,   Message transaction complete
2020-04-12 22:08:13.002 Detail,
2020-04-12 22:08:13.002 Detail, Node050, Removing current message

Jusque là, tout s'est bien passé, la lumière est allumée

Moins de 100 ms…plutôt rapide pour du sécurisé ?
Ensuite ? Et bien Jeedom a prévu de demander l’état du module, en mettant dans la QUEUE un ordre de refresh. Il va donc l’envoyer.

A priori tout se passe bien, prend également environ 100ms, et représente les lignes 30 à 74 de ton fichier de log. Si tu as compris l’analyse faite ci-dessus, tu as tous les éléments pour comprendre chaque ligne du fichier de log ici aussi.

• Jeedom envoie Nonce_Get
• 050 accuse réception
• 050 envoie Nonce_Report
• Jeedom accuse réception
• Jeedom envoie la commande refresh de manière chiffrée
• 050 accuse réception
  => Maintenant, la balle est dans le camp de 050, qui doit envoyer un message (celui de la nouvelle valeur). Comme la clé change à chaque message, on ré-applique l’algorithme d’échange des des index de clés
• 050 envoie Nonce_Get
• Jeedom accuse réception
• Jeedom envoie Nonce_Report
• 050 accuse réception
• 050 envoie son message chiffré (son état)
• Jeedom accuse réception
• Jeedom considère l’échange terminé
• Jeedom notifie au travers de son système événementiel la nouvelle valeur du module

2020-04-12 22:08:13.129 Detail, Node050, Notification: ValueChanged

A présent, la queue du contrôleur doit être vide

Et tout s’est passé en moins de 200ms

Suite à ça, le module 97 va spontanément et au milieu de tout ça remonter un changement d’état sur la consommation, de manière non sécurisé (car pas d’échange de NONCE). Ca semble se passer correctement d’après les logs.

2020-04-12 22:08:13.490 Detail, Node097,   Received: 0x01, 0x0c, 0x00, 0x04, 0x00, 0x61, 0x06, 0x31, 0x05, 0x04, 0x22, 0x00, 0x56, 0xd4
2020-04-12 22:08:13.490 Detail,
2020-04-12 22:08:13.490 Info, Node097, Received SensorMultiLevel report from node 97, instance 1, Power: value=8.6W
2020-04-12 22:08:13.490 Detail, Node097, Refreshed Value: old value=2.5, new value=8.6, type=decimal
2020-04-12 22:08:13.490 Detail, Node097, Changes to this value are not verified
2020-04-12 22:08:13.490 Detail, Node097, Notification: ValueChanged

On en arrive au pseudo-probleme rencontré

Enfin, après tout çà, le module 050 va spontanément remonter sa nouvelle valeur.
On reprend le protocole qu’on commence à connaitre par coeur :

• 050 envoie Nonce_Get
• Jeedom répond

=> Pour une raison (pour laquelle on ne peut que spéculer à l’étape), 050 réémet 22ms plus tard la demande de Nonce_Get.

Pourquoi ? Spéculons...

Partons du principe que Jeedom a reçu le 1er message, puisqu’il est dans les logs. Hypothèses (non exhaustives - il est quand même 3h du mat’ et ça fait une bonne heure que je rédige ce message) :

1) Jeedom a répondu dans les temps
1.1) Problème de communication entre les 2 modules (le message a bien été émis par Jeesom, mais n’est pas arrivé à cause d’une perturbation électromagnétique (ça peut arriver, c’est pourquoi Zwave fait plusieurs tentatives et demande systématiquement des accusés réception). Quand c’est ça, il faut remettre en cause le positionnement des éléments principalement.
1.1.1) Si l’ordre n’avait pas été reçu, ce qui n’est pas le cas ici, il faudrait alors vérifier que l’équipement a bien plusieurs routes possibles pour communiquer avec le destinataire du message. En effet, si une seule route possible, les tentatives pour faire parvenir le message à destination s’arrêteront rapidement.
1.2) Si le positionnement a été remis en cause, et que ce n’est pas la raison 1.1, alors c’est peut-être une défaillance du module qui a émis par erreur une 2ème fois la requête ? Si cela arrive que sur un module et toujours le même, pourquoi pas, la garantie des équipements est là pour ça…
2) Jeedom n’a pas réussi à répondre dans les temps
2.1) Il était occupé à faire autre chose ? Les mécanismes de retry (ZWave) sont là pour couvrir ce genre de cas. Rien à faire dans ce cas mais on devrait voir de l’activité dans les logs ayant lieu en mêmes temps. Donc ici on dirait que ce n’est pas ça.
2.2) Représentation du maillage en désaccord avec la réalité. Jeedom a bien essayé d’émettre selon les informations de routage qu’il possède, mais ce ne sont pas les bonnes infos. Là il suffit de soigner le réseau et vérifier que tous les équipements ont bien communiqués pour se mettre à jour (réveiller les noeuds à piles). Ensuite, redémarrer le démon Z-Wave pour visualiser les bonnes infos dans la table de routage.
2.3) Problème d’alimentation instable du contrôleur ZWave ? De nombreux témoignages indiquent avoir des messages non émis et des erreurs « ERROR: ZW_SEND_DATA could not be delivered to Z-Wave stack ». Certaines personnes ont résolu ce problème en connectant le dongle ZWave sur un hub USB auto-alimenté. (Je note que tu es déjà familiarisé avec ce problème puisque tu en as un, mais je note aussi que ton dongle ZWave est branché en direct sur ton Jeedom). Je ne dis pas que c’est ça, je dis juste que c’est « une » possibilité. Pour le savoir, il suffit de brancher ton dongle USB sur un hub USB auto-alimenté (qui n’est pas lui même surchargé pour être sûr qu’il fourni bien l’électricité requise - juste le temps de confirmer/infirmer cette hypothèse).
2.4) Problème quelconque, instabilité pouvant résulter de l’architecture matériel, (le raspberry Pi, le QNAP, l’Odroid, peu importe ce qui est utilisé) engendrant un problème d’accès spontané à la ressource USB. Pour s’assurer que ce n’est pas ça, commencer par changer de port USB. Sinon essayer une autre architecture matérielle. (c’est galère, donc à faire en dernier lieu).

Voila un peu pour le raisonnement de principe.
Bonne journée, et bon diagnostique,
Pierre (Mav3656) - Helper Officiel Jeedom

[Bison]

Salut,

C’est TTC compris ou pas sur ce site (ali) ? Ou alors il faut rajouter les frais de dédouanage je pige pas trop et je me suis déjà fait avoir avec un truc qui venait de chine…

Merci (et désolé pour le HS).

Bison