Quelques comportements étranges - Calaos v3

[Arnaud]

Bonjour Raoul, 

Ca fait maintenant quelques mois que je tourne en v3, qui fonctionne bien. 

Néanmoins, de temps en temps j'observe des comportements étranges sans vraiment identifier de bug flagrant. Je m'explique.

* Ecran de home cinéma
Après un film, je remonte l'écran motorisé du home cinéma. Comme l'écran n'a plus de fin de course automatique (panne), je fais une fermeture avec un "impulse up 21850". Cela fonctionne très bien mais de temps en temps cela tourne sans fin, comme si le impulse up avait une durée infinie. Cela se voit facilement parce que l'écran remonte entièrement et tape contre le caisson et j'entend le moteur qui ne s'arrête pas. Un appuie sur un bouton toggle permet de l'arrêter. L'impulse est appelé via un scénario.


* Arrosage gouttes à gouttes. 
Même principe, j'ai un scénario ouvrant une électro-vanne d'arrosage la nuit. Il ne fait qu'une seule action qui est un "impulse 7200000" pour une durée de 2h. Ce matin l'arrosage tournait encore, donc 7-8h de plus... J'ai éteint l'électro-vanne via l'écran tactile, la fermeture fonctionne bien. L'impact est que cela me vide les cuves d'eau et fait tourner la pompe à vide (fusillée et réparée durant le mois dernier). 

Les points communs sont un scénario et un impulse :-) 

Si besoin de log ou autres, n'hésites pas,

merci, arnaud.

[raoulh]

Salut,

Est ce que calaos_server crash? Il faudrait voir avec un systemctl status l'uptime de calaos_server pour voir si il a ete redemarré ou non.

En fait si il crash c'est le seul moment ou il pert le timer en court. Ca expliquerai pourquoi ca se n'arrete pas...

[Arnaud]

Je me demandais comment avoir l'info, nickel voici le résultat de la commande:

● calaos-server.service - Calaos home automation server service
  Loaded: loaded (/lib/systemd/system/calaos-server.service; enabled; vendor preset: enabled)
  Active: active (running) since Wed 2020-08-26 09:27:49 CEST; 5h 47min ago
 Process: 3207 ExecStartPre=/bin/mkdir -p /home/root/.cache/calaos /etc/calaos (code=exited, status=0/SUCCESS)
Main PID: 3208 (calaos_server)
   Tasks: 3 (limit: 4915)
  Memory: 12.2M
  CGroup: /system.slice/calaos-server.service
          ├─3208 /usr/bin/calaos_server --config /etc/calaos --cache /home/root/.cache/calaos
          └─3210 /usr/bin/calaos_wago --socket /tmp/calaos_proc_6c0a4773-6cd3-a99d-3b6b-a5cfc7259a24_wago_3208 --namespace wago 192.168.0.1 502

Aug 26 15:15:01 intel-corei7-64 calaos_server[3208]: [INF] output (IntValue.cpp:122) intern_33: got action, 391
Aug 26 15:15:01 intel-corei7-64 calaos_server[3208]: [INF] datalogger (DataLogger.cpp:118) send value Conso\ électrique\ Sensor\ 1,room=Cellier value=391 1598447701283746098
Aug 26 15:15:01 intel-corei7-64 calaos_server[3208]: [CRI] network (HttpClient.cpp:151) Error sending data ! Closing connection.
Aug 26 15:15:03 intel-corei7-64 calaos_server[3208]: [INF] output (IntValue.cpp:122) intern_35: got action, 154
Aug 26 15:15:03 intel-corei7-64 calaos_server[3208]: [INF] datalogger (DataLogger.cpp:118) send value Conso\ électrique\ Sensor\ 3,room=Cellier value=154 1598447703302659764
Aug 26 15:15:03 intel-corei7-64 calaos_server[3208]: [CRI] network (HttpClient.cpp:151) Error sending data ! Closing connection.
Aug 26 15:15:05 intel-corei7-64 calaos_server[3208]: [INF] output (IntValue.cpp:122) intern_34: got action, 0
Aug 26 15:15:05 intel-corei7-64 calaos_server[3208]: [INF] datalogger (DataLogger.cpp:118) send value Conso\ électrique\ Sensor\ 2,room=Cellier value=0 1598447705627264021
Aug 26 15:15:05 intel-corei7-64 calaos_server[3208]: [CRI] network (HttpClient.cpp:151) Error sending data ! Closing connection.
Aug 26 15:15:06 intel-corei7-64 calaos_server[3208]: [INF] websocket (WebSocket.cpp:446) Received a PONG back in 00:00.0005


root@intel-corei7-64:~# date
Wed Aug 26 15:16:47 CEST 2020

Vers cette heure là j'ai fait un push policy pour y ajouter des fermetures d'électro-vannes à 2h du matin et au boot, histoire de pallier au problème pour l'instant. L'uptime correspondrait à ce push ? 
Sinon côté redémarrage réel, ce n'est pas avant quelques temps. 

Quoique... j'ai enregistré la nouvelle configuration à 8h42 ce matin et j'enregistre toujours au moment de faire le push, soit 45mn avant l'heure indiquée par l'uptime.

[raoulh]

Quand tu fais un push de la config, il redemarre oui. Donc c'est normal.

[Arnaud]

Ok, par contre 45mn de délai entre le push hier matin et le restart n'est pas normal.

Je viens de refaire un status à l'instant:

Last login: Wed Aug 26 16:00:13 on console
You have mail.
(base) iBoz-2:~ Boz$ ssh root@calaos
root@intel-corei7-64:~# systemctl status calaos-server
● calaos-server.service - Calaos home automation server service
  Loaded: loaded (/lib/systemd/system/calaos-server.service; enabled; vendor preset: enabled)
  Active: active (running) since Wed 2020-08-26 15:35:46 CEST; 17h ago
 Process: 21527 ExecStartPre=/bin/mkdir -p /home/root/.cache/calaos /etc/calaos (code=exited, status=0/SUCCESS)
Main PID: 21528 (calaos_server)
   Tasks: 3 (limit: 4915)
  Memory: 13.9M
  CGroup: /system.slice/calaos-server.service
          ├─21528 /usr/bin/calaos_server --config /etc/calaos --cache /home/root/.cache/calaos
          └─21530 /usr/bin/calaos_wago --socket /tmp/calaos_proc_fe138eb5-c719-b4c6-b76a-6cebdd27497c_wago_21528 --namespace wago 192.168.0.1 502

Aug 27 08:42:53 intel-corei7-64 calaos_server[21528]: [CRI] network (HttpClient.cpp:151) Error sending data ! Closing connection.
Aug 27 08:42:57 intel-corei7-64 calaos_server[21528]: [INF] output (IntValue.cpp:122) intern_35: got action, 150
Aug 27 08:42:57 intel-corei7-64 calaos_server[21528]: [INF] datalogger (DataLogger.cpp:118) send value Conso\ électrique\ Sensor\ 3,room=Cellier value=150 1598510577763291790
Aug 27 08:42:57 intel-corei7-64 calaos_server[21528]: [CRI] network (HttpClient.cpp:151) Error sending data ! Closing connection.
Aug 27 08:42:59 intel-corei7-64 calaos_server[21528]: [INF] output (IntValue.cpp:122) intern_33: got action, 398
Aug 27 08:42:59 intel-corei7-64 calaos_server[21528]: [INF] datalogger (DataLogger.cpp:118) send value Conso\ électrique\ Sensor\ 1,room=Cellier value=398 1598510579790202422
Aug 27 08:42:59 intel-corei7-64 calaos_server[21528]: [CRI] network (HttpClient.cpp:151) Error sending data ! Closing connection.
Aug 27 08:43:02 intel-corei7-64 calaos_server[21528]: [INF] output (IntValue.cpp:122) intern_34: got action, 0
Aug 27 08:43:02 intel-corei7-64 calaos_server[21528]: [INF] datalogger (DataLogger.cpp:118) send value Conso\ électrique\ Sensor\ 2,room=Cellier value=0 1598510582532912587
Aug 27 08:43:02 intel-corei7-64 calaos_server[21528]: [CRI] network (HttpClient.cpp:151) Error sending data ! Closing connection.

Il y a eu un restart à 15h35, hors je n'ai rien fait hier après-midi...
Y a-t-il un log où l'on peut voir les crash/stop/start du service peut-être ? Sinon je peux ajouter une règle atBoot pour me faire un push sur le smartphone.

En fouillant un peu, quelques pistes (ou pas :-) )
Le serveur lui-même est uptime depuis longtemps, pas de soucis.
root@intel-corei7-64:~# uptime
08:59:33 up 24 days, 13:43,  1 user,  load average: 0.07, 0.04, 0.00

Dans le /var/log/messages:

Aug 27 13:15:46 intel-corei7-64 daemon.err ntpd[491]: frequency file /etc/ntp.drift.TEMP: Permission denied 

Le fichier contient des milliers de lignes identiques, chaque 3 secondes:
Aug 27 13:16:20 intel-corei7-64 authpriv.err agetty[21355]: /dev/ttyS2 : pas un terminal                                                                         
Aug 27 13:16:23 intel-corei7-64 authpriv.err agetty[21356]: /dev/ttyS1 : pas un terminal                                                                         
Aug 27 13:16:27 intel-corei7-64 authpriv.err agetty[21359]: /dev/ttyS0 : pas un terminal                                                                         
Aug 27 13:16:30 intel-corei7-64 authpriv.err agetty[21361]: /dev/ttyS2 : pas un terminal                      1                                                   
Aug 27 13:16:33 intel-corei7-64 authpriv.err agetty[21363]: /dev/ttyS1 : pas un terminal                  d                                                       
Aug 27 13:16:37 intel-corei7-64 authpriv.err agetty[21366]: /dev/ttyS0 : pas un terminal                                                                         
Aug 27 13:16:40 intel-corei7-64 authpriv.err agetty[21367]: /dev/ttyS2 : pas un terminal                                                                         
Aug 27 13:16:43 intel-corei7-64 authpriv.err agetty[21368]: /dev/ttyS1 : pas un terminal                                                                         
Aug 27 13:16:47 intel-corei7-64 authpriv.err agetty[21370]: /dev/ttyS0 : pas un terminal                                                                         
Aug 27 13:16:50 intel-corei7-64 authpriv.err agetty[21372]: /dev/ttyS2 : pas un terminal                                                                         
Aug 27 13:16:20 intel-corei7-64 authpriv.err agetty[21355]: /dev/ttyS2 : pas un terminal                                                                         
Aug 27 13:16:23 intel-corei7-64 authpriv.err agetty[21356]: /dev/ttyS1 : pas un terminal                                                                         
Aug 27 13:16:27 intel-corei7-64 authpriv.err agetty[21359]: /dev/ttyS0 : pas un terminal                                                                         
Aug 27 13:16:30 intel-corei7-64 authpriv.err agetty[21361]: /dev/ttyS2 : pas un terminal                      1                                                   
Aug 27 13:16:33 intel-corei7-64 authpriv.err agetty[21363]: /dev/ttyS1 : pas un terminal                  d                                                       
Aug 27 13:16:37 intel-corei7-64 authpriv.err agetty[21366]: /dev/ttyS0 : pas un terminal                                                                         
Aug 27 13:16:40 intel-corei7-64 authpriv.err agetty[21367]: /dev/ttyS2 : pas un terminal                                                                         
Aug 27 13:16:43 intel-corei7-64 authpriv.err agetty[21368]: /dev/ttyS1 : pas un terminal                                                                         
Aug 27 13:16:47 intel-corei7-64 authpriv.err agetty[21370]: /dev/ttyS0 : pas un terminal                                                                         
Aug 27 13:16:50 intel-corei7-64 authpriv.err agetty[21372]: /dev/ttyS2 : pas un terminal                                                                         

Le log le plus ancien date de ce matin 10h40 (là il est 13h36) dans messages.0. Pas plus ancien.. 
Le wtmp fait 704Mo.

Et dans le dmesg | grep calaos_server:
[166020.503090] traps: calaos_server[26750] general protection ip:7f123936857f sp:7ffd96c2f158 error:0 in libstdc++.so.6.0.25[7f123934e000+ad000]
[342669.461394] calaos_server[29178]: segfault at 9 ip 00000000006457a9 sp 00007fff57b0ea20 error 4 in calaos_server[40e000+2e2000]
[342669.461410] Code: 44 24 18 01 48 8d 7c 24 20 e8 f3 9e dc ff 49 8b 5c 24 08 4c 39 eb 74 2e 66 0f 1f 84 00 00 00 00 00 48 8b 7b 10 48 85 ff 74 14 <48> 8b 47 08 48 85 c0 74 0b 80 7b 18 00 75 05 48 89 ee ff d0 48 8b
[430435.559499] calaos_server[29320]: segfault at 463325206d ip 00007f0713604306 sp 00007ffeb5aa1938 error 4 in libc-2.29.so[7f07134cd000+142000]
[430435.559514] Code: 66 0f ef d1 66 0f 38 17 c2 0f 83 bd 09 00 00 f3 0f 6f 4f cf f3 0f 6f 56 cf b2 cf 66 0f ef d1 66 0f 38 17 c2 0f 83 a2 09 00 00 <f3> 0f 6f 4f df f3 0f 6f 56 df b2 df 66 0f ef d1 66 0f 38 17 c2 0f
[442879.757975] calaos_server[30304]: segfault at 1 ip 00007f4dfad9fc46 sp 00007fff4c55ced0 error 4 in libc-2.29.so[7f4dfad40000+142000]
[442879.757990] Code: 84 42 ff ff ff 0f 1f 80 00 00 00 00 4a 8d 0c e0 48 8b 51 40 48 85 d2 0f 84 2a ff ff ff 48 81 fb ff 03 00 00 0f 87 ba 01 00 00 <48> 8b 32 48 89 71 40 42 80 2c 20 01 48 c7 42 08 00 00 00 00 48 83
[483251.673057] calaos_server[8207]: segfault at 1bc9e61d ip 00007f2c96c545d6 sp 00007ffcceec0138 error 4 in libc-2.29.so[7f2c96b1d000+142000]
[483251.673072] Code: 66 0f ef d1 66 0f 38 17 c2 0f 83 ed 06 00 00 f3 0f 6f 57 cc f3 0f 6f 4e cc b2 cc 66 0f ef d1 66 0f 38 17 c2 0f 83 d2 06 00 00 <f3> 0f 6f 57 dc f3 0f 6f 4e dc b2 dc 66 0f ef d1 66 0f 38 17 c2 0f
[532142.415450] calaos_server[9494]: segfault at 0 ip 00007fd8059575d6 sp 00007ffd63ecb518 error 4 in libc-2.29.so[7fd805820000+142000]
[532142.415465] Code: 66 0f ef d1 66 0f 38 17 c2 0f 83 ed 06 00 00 f3 0f 6f 57 cc f3 0f 6f 4e cc b2 cc 66 0f ef d1 66 0f 38 17 c2 0f 83 d2 06 00 00 <f3> 0f 6f 57 dc f3 0f 6f 4e dc b2 dc 66 0f ef d1 66 0f 38 17 c2 0f
[745359.570314] traps: calaos_server[17742] general protection ip:7f8d1c18757f sp:7fff43ff14d8 error:0 in libstdc++.so.6.0.25[7f8d1c16d000+ad000]
[1185780.591848] calaos_server[32483]: segfault at 31 ip 00007f84daaaa482 sp 00007fffb3660718 error 4 in libc-2.29.so[7f84da973000+142000]
[1185780.591863] Code: f8 48 39 c1 0f 85 61 08 00 00 31 c0 c3 66 66 2e 0f 1f 84 00 00 00 00 00 8b 47 fa 8b 4e fa 39 c1 0f 85 51 08 00 00 0f b7 4e fe <0f> b7 47 fe 38 c8 0f 85 62 08 00 00 25 ff ff 00 00 81 e1 ff ff 00
[1394271.033483] calaos_server[9105]: segfault at 100 ip 00007fd69bd8f5d6 sp 00007ffcdd4b59a8 error 4 in libc-2.29.so[7fd69bc58000+142000]
[1394271.033498] Code: 66 0f ef d1 66 0f 38 17 c2 0f 83 ed 06 00 00 f3 0f 6f 57 cc f3 0f 6f 4e cc b2 cc 66 0f ef d1 66 0f 38 17 c2 0f 83 d2 06 00 00 <f3> 0f 6f 57 dc f3 0f 6f 4e dc b2 dc 66 0f ef d1 66 0f 38 17 c2 0f
[1541231.505204] traps: calaos_server[20195] general protection ip:7fe04f42a57f sp:7ffceb164b98 error:0 in libstdc++.so.6.0.25[7fe04f410000+ad000]
[1556216.125413] calaos_server[12396]: segfault at 9 ip 00000000006457a9 sp 00007ffd4bc4d540 error 4 in calaos_server[40e000+2e2000]
[1556216.125427] Code: 44 24 18 01 48 8d 7c 24 20 e8 f3 9e dc ff 49 8b 5c 24 08 4c 39 eb 74 2e 66 0f 1f 84 00 00 00 00 00 48 8b 7b 10 48 85 ff 74 14 <48> 8b 47 08 48 85 c0 74 0b 80 7b 18 00 75 05 48 89 ee ff d0 48 8b
[1568682.322113] calaos_server[24848]: segfault at 59 ip 00007fac17414e26 sp 00007ffcc99d1c60 error 4 in libstdc++.so.6.0.25[7fac1737d000+ad000]
[1568682.322127] Code: 17 eb 0b 90 48 83 e8 01 48 83 f8 ff 74 06 40 38 34 02 74 f0 c3 66 2e 0f 1f 84 00 00 00 00 00 0f 1f 44 00 00 55 53 48 83 ec 08 <48> 8b 5f 08 48 8b 6e 08 48 89 da 48 39 dd 48 0f 46 d5 48 85 d2 74
[1654201.440825] calaos_server[2833]: segfault at 9 ip 00000000006457a9 sp 00007ffd01762250 error 4 in calaos_server[40e000+2e2000]
[1654201.440840] Code: 44 24 18 01 48 8d 7c 24 20 e8 f3 9e dc ff 49 8b 5c 24 08 4c 39 eb 74 2e 66 0f 1f 84 00 00 00 00 00 48 8b 7b 10 48 85 ff 74 14 <48> 8b 47 08 48 85 c0 74 0b 80 7b 18 00 75 05 48 89 ee ff d0 48 8b
[1704499.604761] calaos_server[8694]: segfault at f8155092 ip 00007f540d0005d6 sp 00007ffe2d24f0c8 error 4 in libc-2.29.so[7f540cec9000+142000]
[1704499.604775] Code: 66 0f ef d1 66 0f 38 17 c2 0f 83 ed 06 00 00 f3 0f 6f 57 cc f3 0f 6f 4e cc b2 cc 66 0f ef d1 66 0f 38 17 c2 0f 83 d2 06 00 00 <f3> 0f 6f 57 dc f3 0f 6f 4e dc b2 dc 66 0f ef d1 66 0f 38 17 c2 0f
[1998140.733900] traps: calaos_server[21830] general protection ip:7fc49de355d6 sp:7fff3ce618c8 error:0 in libc-2.29.so[7fc49dcfe000+142000]
[2038296.677450] traps: calaos_server[854] general protection ip:628081 sp:7fff929a7c10 error:0 in calaos_server[40e000+2e2000]
[2060372.889940] calaos_server[3208]: segfault at 69 ip 0000000000628081 sp 00007ffccdfc9220 error 4 in calaos_server[40e000+2e2000]
[2060372.889955] Code: 24 08 4d 85 ff 0f 84 d6 00 00 00 4c 8b 73 60 4c 8b 63 58 49 89 ed 4d 89 f9 eb 0f 66 0f 1f 44 00 00 4d 8b 49 18 4d 85 c9 74 5d <4d> 8b 51 28 4c 89 f2 4d 39 f2 49 0f 46 d2 48 85 d2 74 24 49 8b 79

[Arnaud]

● calaos-server.service - Calaos home automation server service
  Loaded: loaded (/lib/systemd/system/calaos-server.service; enabled; vendor preset: enabled)
  Active: active (running) since Sat 2020-08-29 20:33:11 CEST; 2 days ago
 Process: 21162 ExecStartPre=/bin/mkdir -p /home/root/.cache/calaos /etc/calaos (code=exited, status=0/SUCCESS)
Main PID: 21163 (calaos_server)
   Tasks: 3 (limit: 4915)
  Memory: 19.0M
  CGroup: /system.slice/calaos-server.service
          ├─21163 /usr/bin/calaos_server --config /etc/calaos --cache /home/root/.cache/calaos
          └─21165 /usr/bin/calaos_wago --socket /tmp/calaos_proc_c0ae1560-5e68-c7ef-d3fe-aa91bc22fd03_wago_21163 --namespace wago 192.168.0.1 502

Sep 01 08:53:03 intel-corei7-64 calaos_server[21163]: [INF] output (IntValue.cpp:122) intern_35: got action, 140
Sep 01 08:53:03 intel-corei7-64 calaos_server[21163]: [INF] datalogger (DataLogger.cpp:118) send value Conso\ électrique\ Sensor\ 3,room=Cellier val>
Sep 01 08:53:03 intel-corei7-64 calaos_server[21163]: [CRI] network (HttpClient.cpp:151) Error sending data ! Closing connection.
Sep 01 08:53:03 intel-corei7-64 calaos_server[21163]: [INF] websocket (WebSocket.cpp:446) Received a PONG back in 00:00.0001
Sep 01 08:53:04 intel-corei7-64 calaos_server[21163]: [INF] output (IntValue.cpp:122) intern_33: got action, 389
Sep 01 08:53:04 intel-corei7-64 calaos_server[21163]: [INF] datalogger (DataLogger.cpp:118) send value Conso\ électrique\ Sensor\ 1,room=Cellier val>
Sep 01 08:53:04 intel-corei7-64 calaos_server[21163]: [CRI] network (HttpClient.cpp:151) Error sending data ! Closing connection.
Sep 01 08:53:06 intel-corei7-64 calaos_server[21163]: [INF] output (IntValue.cpp:122) intern_34: got action, 0
Sep 01 08:53:06 intel-corei7-64 calaos_server[21163]: [INF] datalogger (DataLogger.cpp:118) send value Conso\ électrique\ Sensor\ 2,room=Cellier val>
Sep 01 08:53:06 intel-corei7-64 calaos_server[21163]: [CRI] network (HttpClient.cpp:151) Error sending data ! Closing connection.

Le 29/08 je n'étais pas chez moi du week-end, j'ai bien un restart assez fréquent du service calaos-server. A mon avis c'est directement lié à l'exécution d'un scénario et/ou d'un impulse parce que quand ça plante durant une remontée de l'écran de home cinéma qui ne dure que 10 ou 12 secondes environ... ça serait un hasard improbable que ça plante pile à ce moment là 

[raoulh]

Vu ton log de dmesg, c'est bien calaos_server qui plante.

Pourrait-tu m'envoyer par mail ta config complete, il faut que je puisse le reproduire pour voir d'ou ca vient...

[Arnaud]

Oui bien sûr,
En regardant ce matin il y a un crash il a 14h, donc vers 22h hier soir.
Je t'envoi par email la config.
Thanks

[raoulh]

Salut,

J'ai fait plusieurs tests, et j'arrive pas a reproduire ton crash avec ta config. J'ai testé les impulses dans tous les sens et ca crash pas...
De plus j'utilise aussi des impulses chez moi sur mon install et j'ai pas de crash.

Il me faudrait une autre piste a chercher.....

[Arnaud]

Hum.. flûte.
Je vais mettre un scénario en place avec timer, genre qui se déclenche chaque 15mn pour générer du log.
Vais essayer de faire ça courant semaine prochaine.