Instabilité démon suite passage en beta

dvb · Mars 12, 2023, 9:45

Je viens de migrer de Modbus « dernière stable » → beta.
→ Tout s’est bien passé pour l’installation et le redémarrage.

Manips effectuées pour info :

Désactivation équipement
Arrêt démon
Désactivation plugin
Installation plugin beta → la maj des dépendances s’est lancée toute seule
Paramétrage équipement → onglet équipement (l’option unit ID a disparu) + onglet commandes.
Activation équipement.
Vérification démon actif → OK
Vérification logs → OK

Par contre, j’ai un souci de stabilité côté démon :
→ Il est passé en rouge statut NOK.
→ Le centre de message indique « Attention je pense qu’il y a un soucis avec le démon que j’ai relancé plus de 3 fois consécutivement »

→ En regardant les logs, le démon se connecte, récupère les infos, puis n’arrive plus à se connecter, puis se reconnecte, etc… de manière cyclique. Voici un extrait des logs :

Je suis dispo pour faire des manips.

> ...
> [2023-03-12 22:36:18][DEBUG] : deamon_info = {"state":"nok","launchable":"ok"}
> [2023-03-12 22:36:18][DEBUG] : deamon_info = {"state":"nok","launchable":"ok"}
> [2023-03-12 22:36:18][DEBUG] : deamon_info = {"state":"nok","launchable":"ok"}
> [2023-03-12 22:36:18][DEBUG] : deamon_info = {"state":"nok","launchable":"ok"}
> [2023-03-12 22:36:18][DEBUG] : deamon_info = {"state":"nok","launchable":"ok"}
> [2023-03-12 22:36:22][DEBUG] : Connecting to 192.168.200.151:502.
> [2023-03-12 22:36:22][DEBUG] : Connecting.
> [2023-03-12 22:36:22][DEBUG] : Client connected to modbus server
> [2023-03-12 22:36:22][INFO] : Protocol made connection.
> [2023-03-12 22:36:22][INFO] : Connected to 192.168.200.151:502.
> [2023-03-12 22:36:22][DEBUG] : send: 0x21 0x1a 0x0 0x0 0x0 0x6 0x0 0x3 0x3 0x34 0x0 0x1
> [2023-03-12 22:36:22][DEBUG] : Adding transaction 8474
> [2023-03-12 22:36:22][DEBUG] : recv: 0x21 0x1a 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x3 0x6a
> [2023-03-12 22:36:22][DEBUG] : Processing: 0x21 0x1a 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x3 0x6a
> [2023-03-12 22:36:22][DEBUG] : Factory Response[ReadHoldingRegistersResponse': 3]
> [2023-03-12 22:36:22][DEBUG] : Getting transaction 8474
> [2023-03-12 22:36:22][DEBUG] : [874]
> [2023-03-12 22:36:22][DEBUG] : PyModbusClient: read value for 820 grid to system (command id 17083): 874
> [2023-03-12 22:36:22][DEBUG] : send: 0x21 0x1b 0x0 0x0 0x0 0x6 0x0 0x3 0x3 0x49 0x0 0x1
> [2023-03-12 22:36:22][DEBUG] : Adding transaction 8475
> [2023-03-12 22:36:22][DEBUG] : recv: 0x21 0x1b 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0xff 0xfe
> [2023-03-12 22:36:22][DEBUG] : Processing: 0x21 0x1b 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0xff 0xfe
> [2023-03-12 22:36:22][DEBUG] : Factory Response[ReadHoldingRegistersResponse': 3]
> [2023-03-12 22:36:22][DEBUG] : Getting transaction 8475
> [2023-03-12 22:36:22][DEBUG] : [65534]
> [2023-03-12 22:36:22][DEBUG] : PyModbusClient: read value for 841 Battery Current (System) (command id 17087): -2
> [2023-03-12 22:36:22][DEBUG] : send: 0x21 0x1c 0x0 0x0 0x0 0x6 0x0 0x3 0x3 0x4a 0x0 0x1
> [2023-03-12 22:36:22][DEBUG] : Adding transaction 8476
> [2023-03-12 22:36:22][DEBUG] : recv: 0x21 0x1c 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0xff 0xf6
> [2023-03-12 22:36:22][DEBUG] : Processing: 0x21 0x1c 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0xff 0xf6
> [2023-03-12 22:36:22][DEBUG] : Factory Response[ReadHoldingRegistersResponse': 3]
> [2023-03-12 22:36:22][DEBUG] : Getting transaction 8476
> ...
> [2023-03-12 22:36:22][DEBUG] : [2904]
> [2023-03-12 22:36:22][DEBUG] : PyModbusClient: read value for 3719 Max power J tracker3 (command id 17200): 2904
> [2023-03-12 22:36:22][DEBUG] : send: 0x21 0x3e 0x0 0x0 0x0 0x6 0x0 0x3 0xe 0x8f 0x0 0x1
> [2023-03-12 22:36:22][DEBUG] : Adding transaction 8510
> [2023-03-12 22:36:22][DEBUG] : recv: 0x21 0x3e 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x0
> [2023-03-12 22:36:22][DEBUG] : Processing: 0x21 0x3e 0x0 0x0 0x0 0x5 0x0 0x3 0x2 0x0 0x0
> [2023-03-12 22:36:22][DEBUG] : Factory Response[ReadHoldingRegistersResponse': 3]
> [2023-03-12 22:36:22][DEBUG] : Getting transaction 8510
> [2023-03-12 22:36:22][DEBUG] : [0]
> [2023-03-12 22:36:22][DEBUG] : PyModbusClient: read value for 3727  Power tracker3 (command id 17196): 0
> [2023-03-12 22:36:22][INFO] : Send to jeedom :  {'values': {'17083': 874, '17087': -2, '17086': -10, '16026': 0, '16085': 0, '17629': 150, '16030': 350, '16028': 75, '15430': 0, '16086': 869, '16031': 750, '17169': 501, '16082': 150, '16027': 176, '17233': 8860, '17081': 9341, '17079': 0, '17126': 35, '17082': 42, '17209': 2168, '17197': 2358, '17193': 0, '17123': 37, '17119': 42, '17210': 2151, '17198': 2218, '17194': 0, '17124': 34, '17120': 39, '17211': 1865, '17199': 2327, '17195': 0, '17125': 44, '17121': 53, '17212': 2761, '17200': 2904, '17196': 0}}
> [2023-03-12 22:36:22][INFO] : Protocol lost connection.
> [2023-03-12 22:36:22][DEBUG] : Client disconnected from modbus server: None
> [2023-03-12 22:36:22][DEBUG] : Starting new HTTP connection (1): localhost:80
> [2023-03-12 22:36:22][DEBUG] : jeemymodbus.php: $result *{"values":{"17083":874,"17087":-2,"17086":-10,"16026":0,"16085":0,"17629":150,"16030":350,"16028":75,"15430":0,"16086":869,"16031":750,"17169":501,"16082":150,"16027":176,"17233":8860,"17081":9341,"17079":0,"17126":35,"17082":42,"17209":2168,"17197":2358,"17193":0,"17123":37,"17119":42,"17210":2151,"17198":2218,"17194":0,"17124":34,"17120":39,"17211":1865,"17199":2327,"17195":0,"17125":44,"17121":53,"17212":2761,"17200":2904,"17196":0}}* type: array
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 820 grid to system -> new value: 874
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 841 Battery Current (System) -> new value: -0.2
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 842 Battery Power (System) CHARGE  -> new value: -1
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 851 PV_DC-coupled_current  -> new value: 0
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 772 Battery current (solar charger) -> new value: 0
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 2705 DVCC system max charge current -> new value: 150
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 2901 ESS Minimum SoC (unless grid fails)  -> new value: 35
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 843 Battery SoC (System)  -> new value: 75
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 850 PV - DC-coupled power  -> new value: 0
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 817 System to load -> new value: 869
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 2903 ESS BatteryLife SoC limit (read only) -> new value: 75
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 840 Battery voltage -> new value: 50.1
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 786 Yield_J-1  -> new value: 15
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 784 Yield _J -> new value: 17.6
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 787 PV prod max J-1 -> new value: 8860
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 785 PV prod max J -> new value: 9341
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 789 PV temps réel -> new value: 0
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3712 yield J-1 tracker0 -> new value: 3.5
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3708 yield J tracker0 -> new value: 4.2
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3720 Max power J-1 tracker0 -> new value: 2168
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3716 Max power J tracker0 -> new value: 2358
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3724 Power tracker0 -> new value: 0
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3713 yield J-1 tracker1 -> new value: 3.7
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3709 yield J tracker1 -> new value: 4.2
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3721 Max power J-1 tracker1 -> new value: 2151
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3717 Max power J tracker1 -> new value: 2218
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3725 Power tracker1 -> new value: 0
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3714 yield J-1 tracker2 -> new value: 3.4
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3710 yield J tracker2 -> new value: 3.9
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3722 Max power J-1 tracker2 -> new value: 1865
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3718 Max power J tracker2 -> new value: 2327
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3726  Power tracker2 -> new value: 0
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3715 yield J-1 tracker3 -> new value: 4.4
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3711 yield J tracker3 -> new value: 5.3
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3723 Max power J-1 tracker3 -> new value: 2761
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3719 Max power J tracker3 -> new value: 2904
> [2023-03-12 22:36:22][DEBUG] : jeemodbus.php: Mise à jour cmd 3727  Power tracker3 -> new value: 0
> [2023-03-12 22:36:22][INFO] : jeemodbus.php: Mise à jour des commandes info : '820 grid to system' '841 Battery Current (System)' '842 Battery Power (System) CHARGE ' '851 PV_DC-coupled_current ' '772 Battery current (solar charger)' '2705 DVCC system max charge current' '2901 ESS Minimum SoC (unless grid fails) ' '843 Battery SoC (System) ' '850 PV - DC-coupled power ' '817 System to load' '2903 ESS BatteryLife SoC limit (read only)' '840 Battery voltage' '786 Yield_J-1 ' '784 Yield _J' '787 PV prod max J-1' '785 PV prod max J' '789 PV temps réel' '3712 yield J-1 tracker0' '3708 yield J tracker0' '3720 Max power J-1 tracker0' '3716 Max power J tracker0' '3724 Power tracker0' '3713 yield J-1 tracker1' '3709 yield J tracker1' '3721 Max power J-1 tracker1' '3717 Max power J tracker1' '3725 Power tracker1' '3714 yield J-1 tracker2' '3710 yield J tracker2' '3722 Max power J-1 tracker2' '3718 Max power J tracker2' '3726  Power tracker2' '3715 yield J-1 tracker3' '3711 yield J tracker3' '3723 Max power J-1 tracker3' '3719 Max power J tracker3' '3727  Power tracker3'
> [2023-03-12 22:36:22][DEBUG] : http://localhost:80 "POST /plugins/mymodbus/core/php/jeemymodbus.php?apikey=xxx HTTP/1.1" 200 0
> [2023-03-12 22:36:23][DEBUG] : deamon_info = {"state":"nok","launchable":"ok"}
> [2023-03-12 22:36:23][DEBUG] : deamon_info = {"state":"nok","launchable":"ok"}
> [2023-03-12 22:36:23][DEBUG] : deamon_info = {"state":"nok","launchable":"ok"}
> ...

dvb · Mars 12, 2023, 11:10

Update.
Pas de changement côté logs (le cycle continue).
Par contre, le statut du démon est repassé au vert.

→ Je ne touche à rien, j’attends vos retours.

@+

Michel_F · Mars 13, 2023, 7:38

Salut @dvb,

N’hésite pas à poster les logs depuis une sauvegarde sur plusieurs cycles de polling pour que je me rende compte.

Tu peux poster une capture de la configuration de l’équipement STP ?

J’ai eu ce genre de cas, il faut « jouer » avec la durée du polling et « Garder la connexion ouverte » jusqu’à trouver un bon équilibre.

dvb · Mars 13, 2023, 8:54

Salut @Michel_F

Je viens de regarder les logs, tout est normal ce matin ! Je ne comprends pas, je n’ai touché à rien…

La voici :

Hier soir j’ai essayé de jouer avec « Garder la connexion ouverte » et aussi « RTU sur TCP » en vain. Par contre j’ai laissé le pooling à 10 secondes, car j’ai besoin de réactivité (monitoring de la production en quasi temps réel). Et cela fonctionnait avec l’ancien plugin.

Les questions du jour

J’ai beaucoup trop de logs et j’aimerais passer en mode « error » (pour ne tracer que les problèmes).
Est-ce que cela va fonctionner ? Car les messages « deamon KO » ne semblent pas être taggués [ERROR] mais [DEBUG] :

[2023-03-12 22:36:18][DEBUG] : deamon_info = {« state »:« nok »,« launchable »:« ok »}

Quand faut-il cocher l’option RTU sur TCP ?
L’option « Unit ID » a disparu mais cela fonctionne. C’est géré automatiquement ?

@+

Michel_F · Mars 13, 2023, 9:27

Salut @dvb,

Je ne réponds donc qu’aux questions du jour, mais pour avoir une bonne image de ce qu’il se passe chez toi, les logs du démarrage du démon sur plusieurs cycles me seront utiles en cas de problème.

C’est quelque chose que j’ai remarqué aussi. pymodbus (le module utilisé par le démon) génère plein de log debug depuis la version 3.2.0, Je pense qu’il faut que je lui passe le niveau de log d’une certaine manière que je n’ai pas encore cherchée… C’est dans un coin de ma tête depuis ce week-end et sera mis en place cette semaine.

[2023-03-12 22:36:18][DEBUG] : deamon_info = {« state »:« nok »,« launchable »:« ok »}

Ces messages sont en debug, parce qu’ils informent seulement de l’interrogation du statut, ce n’est pas un événement grave ou remarquable juste de le résultat de l’interrogation à la fin de la fonction. D’ailleurs quand la page de configuration du plugin est affichée (celle où on peut activer le plugin et relancer l’install des dépendances) la fonction est appelée toutes les 5 secondes par le core de Jeedom.

Quand le protocole à utiliser est « RTU over TCP ».
→ C’est spécifique à l’appareil avec lequel tu communiques. Ce n’est pas un point à tester avec ou sans, c’est défini par l’appareil et ne doit plus bouger.

Ce paramètre a été, selon moi, mal géré sur les anciennes versions de pymodbus et logiquement mal compris par Bebel27 et/ou les personnes qui ont développé le plugin que Bebel a repris. C’est une information que j’ai retrouvée en cherchant dans les conversations de remontée de bug sur le git de pymodbus… Donc c’était bien caché !
→ Le paramètre unit représentait en réalité l’adresse de l’esclave et a été changé en slave ce qui est bien plus compréhensible. Pour MyModbus, ils avaient donc utilisé Unit ID et l’avaient utilisé au niveau de l’équipement.

Avec la beta, ce paramètre se trouve dans la configuration des commandes. Comme indiqué dans la doc, il est à 0 par défaut (pour être ignoré) et doit être fixé à l’adresse de l’esclave si un bus série est utilisé.

Comme j’ai réécrit le démon en partant de zéro (la structure d’appel est basée sur le plugin jmqtt ou mqtt2, je ne sais plus) et avec la nouvelle version de pymodbus, je n’ai pas eu de problème avec ce paramètre et ai recherché plus en détail parce que Bebel m’avait informé de l’importance de ce paramètre. Il est en effet important et correctement géré dans la beta.

A+
Michel

Michel_F · Mars 13, 2023, 9:31

Je te laisse lire la doc à ce sujet et analyser les logs au démarrage pour savoir si le polling que tu as configuré n’est pas trop court.

Le plugin s’appelle pareil mais n’a vraiment plus grand chose à voir avec l’ancien. Comme déjà dit, c’est une réécriture complète.

dvb · Mars 13, 2023, 10:18

@Michel_F

Très clair → Compris !

Je sais que 10s de poling c’est très court, mais je tente quand même.

Je surveille le comportement, et te pousserai des logs complets en cas d’anomalie(s).

dvb · Mars 13, 2023, 11:38

@Michel_F
Je n’ai pas détecté de dysfonctionnement dans la journée, par contre je vois passer ça toutes les 10s dans les logs :

4958|[2023-03-14 00:34:02]INFO : Protocol lost connection.
4959|[2023-03-14 00:34:02]DEBUG : Client disconnected from modbus server: None

Avant d’essayer « Garder la connexion ouverte », je préfère que tu jette un oeil.
→ Je te pousse un extrait des logs via MP.

Michel_F · Mars 14, 2023, 12:02

Bien, bonne nouvelle !

Quand aux logs, ce n’est qu’une info générée par pymodbus, rien de grave, juste une info…
tu peux essayer de garder la connexion ouverte, mais si ça génère des erreurs, remets comme maintenant.

Pour moi ta config roule

dvb · Mars 14, 2023, 9:40

Effectivement. Je vais surveiller tes prochaines avancées, en particulier la gestion des logs.

Je viens d’essayer cela fonctionne → plus de messages « lost ».

En effet, sujet clos !

PS : je suis vraiment content d’avoir migré, cette version apporte des avancées sympas !

@+

Michel_F · Mars 14, 2023, 10:23

Et c’est pas fini !