Messages d'erreur dans log openzwave depuis dernière mise à jour

Fabrice · Juin 4, 2020, 4:26

Bonsoir,

Dans mon cas, je l’ai eu qu’une seule fois (c’est encore tout frais mon installation sous Buster).

rootard · Juin 4, 2020, 5:43

+1 c’est arrivé à la dernière maj.

pi@raspberrypi> python --version
Python 2.7.13
pi@raspberrypi> pip --version
pip 20.0.2 from /usr/local/lib/python3.5/dist-packages/pip (python 3.5)
pi@raspberrypi> uname -a
Linux raspberrypi 5.4.42-v7+ #1319 SMP Wed May 20 14:06:11 BST 2020 armv7l GNU/Linux

v3.3.50, dernière version du plugin-zwave

Mips · Juin 4, 2020, 6:15

Ici il y a un problème avec la version de pip.
Ça posera problème lors d’install de dépendances.
Le sujet et la solution est abordé sur d’autres postes.

rootard · Juin 4, 2020, 6:28

Merci du conseil. Je pense que c’est l’apt update qui a installé Python3 comme défaut.
Je pourrais rétrograder en python2 mais mon démon ZWave est vert et c’est ma machine de prod donc je ne vais pas prendre le risque de changer une config qui marche.

neurall · Juin 5, 2020, 2:00

+1 pour moi

Python 2.7.16 + pip 18.1 from /usr/lib/python2.7/dist-packages/pip (python 2.7)

jeedom 4.0.56 sur debian buster tout neuf.

ce message n’apparait que depuis la migration vers jeedom R4, sur la version en 3.X ça n’apparaît pas.

le message d’erreur est généré 2 à 3 fois par jours depuis lors.

[2020-06-04 20:57:52][ERROR] : Critical error on send_changes_async threads can only be started once Unhandled exception in thread started by <bound method _Timer.__bootstrap of <_Timer(Thread-5241471, stopped daemon 139834461861632)>> Traceback (most recent call last): File « /usr/lib/python2.7/threading.py », line 774, in __bootstrap self.__bootstrap_inner() File « /usr/lib/python2.7/threading.py », line 789, in __bootstrap_inner del _limbo[self]

j’ajoute que je viens de regarder le log de mon autre box sous debian mais en V3 et le même message apparaît j’en déduit donc que c’est la maj openzwave et pas le système qui pose pb car les versions de python ne sont pas les mêmes je suis sous stretch sur cette box

stardust · Juin 7, 2020, 1:58

J’ai la même chose avec jeedom 3.3.50 / zwave 3.3.0:

HTTP/1.1 » 200 0
Unhandled exception in thread started by <bound method _Timer.__bootstrap of <_Timer(Thread-12971, stopped daemon 140553467455232)>>
Traceback (most recent call last):
File « /usr/lib/python2.7/threading.py », line 774, in __bootstrap
self.__bootstrap_inner()
File « /usr/lib/python2.7/threading.py », line 789, in __bootstrap_inner
del _limbo[self]
KeyError: <_Timer(Thread-12971, stopped daemon 140553467455232)>

Par contre plus de retour d’état des modules. je ne sais pas c’est lié…

kristobal · Juin 10, 2020, 2:28

Bonjour,
Avant de faire des bétises, est ce bien ça la solution :
pip install --upgrade pip

Fabrice · Juin 10, 2020, 2:35

Bonjour,

Je ne suis pas certain qu’une solution pour cette erreur soit connue.

Ou alors elle est bien cachée.

J’invite ceux qui auraient la solution à la partager.
Merci

kristobal · Juin 10, 2020, 2:37

Merci on va attendre sagement. Pour l’instant j’ai pas vu de dysfonctionnement sur mon reseau mise à part le message dans le log.

bobaxx · Juin 10, 2020, 8:40

Exactement le même souci

j’ai procéder à une sauvegarde du système et j’ai mis à jour pip

On verra demain si le log se remplit

edit : Je ne connais pas la fréquence d’arrivée de ces messages, pour le moment, pas de nouveaux messages

bobaxx · Juin 11, 2020, 6:23

Faux espoir, la même erreur revient dans les logs, cela ne vient pas de la mise à jour de pip visiblement

defmy · Juin 11, 2020, 6:28

Même problème, je pensais être le seul, finalement pas.

C’est arrivé pour moi depuis que j’ai mis à jour le plugin, j’étais à une version avant.
Je n’avais pas fait la dernière car c’était stable, je manquais de temps et je ne voulais pas tout planter. Heureusement que ce n’est pas bloquant.

Fabrice · Juin 16, 2020, 6:50

Bonsoir,

En cherchant, je pense que c’est un problème lié à la version de Python, j’ai trouvé cela :
https://bugs.python.org/issue27908

C’est, à la part la version de Python, carrément le message que nous avons tous !

@Mips : Tu en penses quoi ?

Mips · Juin 16, 2020, 8:04

Question à tout ceux qui n’auront pas le courage de lire tout mon post (ce que je comprend): Est-ce que certains d’entre vous ayant le problème voient ce message dans le log: Issue with the async timer reseting
Si vous voulez savoir pourquoi je pose la question, lisez

@Fabrice, pourquoi dis-tu « à part la version de Python » ? l’issue que ta link touche toutes les version et ne semble pas résolue.
Et effectivement ça semble le problème et vu qu’il y a une race condition (=l’erreur dépend du temps d’exécution de deux codes/instances différentes), cela expliquerait pourquoi cela se produit parfois et pas tous le temps ou chez certains seulement.

Sinon je viens de revérifier les changements du plugin dans la dernière version (qui ne sont pas QUE des changements de documentations ou de traductions):
Cette partie a été changée, fichier jeedom.py, dans ce commit: Merge pull request #185 from jeedom/beta · jeedom/plugin-openzwave@c7558df · GitHub

Peut-être plus clair ici:

L’erreur que certain ont se produit à la ligne 83;
Manifestement il y a eu une tentative de régler un problème (pas celui-ci, un précédent?)

Je dois encore y réfléchir mais je suspecte que le problème se produit quand il y a un add_changes qui se déclenche (une nouvelle info d’un noeud) qui rentrerait dans la condition pour relancer send_changes_async alors que la méthode tourne déjà; ce qui fait que les deux instances en cours essaie de recréer le thread et de le démarrer.
Ca peut se produire si le self.resend_changes.cancel() à la ligne 91 ne peut pas annuler l’exécution (l’annulation n’est pas garantie, faut que le timer soit toujours en attente);

Est-ce que certains d’entre vous voient ce message dans le log: Issue with the async timer reseting ? (bravo à ceux qui ont lu jusqu’ici)

Donc en théorie, on peut avoir un cas de race condition dans le code écrit, sans parler que dans ce code self.lastTimer est utilisé dans les 2 fonctions et que rien n’est fait pour le protéger, ce n’est pas threadsafe: on peut avoir un accès concurrent à la même variable dans 2 threads différents.

Maintenant tout ceci est très compliqué, voir impossible à tester et à reproduire, donc compliqué d’être sur de comment changer le code;
D’autant plus que je ne sais pas exactement quel problème on a voulu résoudre au début.

Et en plus j’ai le sentiment que ça va être peine perdue: j’ai des PR bien plus stupides que ça qui attendent depuis des mois pour lesquels je n’ai aucun retour ni de ludovic ni de loic; dans ce cas aucun espoir de proposer le moindre fix…
Donc tu peux faire remonter cette investigation si tu as un moyen que je n’ai pas car le problème est là quelque part, manque plus que la solution

loic69 · Juin 16, 2020, 8:20

Meme erreur chez moi dans les logs.
Buster installée il y a 2 mois uniquement avec jeedom 4 up-to-date.
Mon reseau zwave fonctionne cependement parfaitement.

Fabrice · Juin 16, 2020, 8:29

Bonsoir et MERCI pour ce détail,

Il serait bien dommage de n’avoir pas pris le temps de lire ta réponse au vue de l’effort que tu y a consacré pour nous expliquer la situation (et surtout, d’avoir remarqué ces changements).

En ce qui me concerne, je n’ai pas les messages que tu indique, mais juste ces deux là :

Log : openzwave

[2020-06-03 00:34:47][ERROR] : Critical error on  send_changes_async threads can only be started once
Unhandled exception in thread started by <bound method _Timer.__bootstrap of <_Timer(Thread-45204, stopped daemon 1879041120)>>
Traceback (most recent call last):
File "/usr/lib/python2.7/threading.py", line 774, in __bootstrap
self.__bootstrap_inner()
File "/usr/lib/python2.7/threading.py", line 789, in __bootstrap_inner
del _limbo[self]
KeyError: <_Timer(Thread-45204, stopped daemon 1879041120)>

Et 12 jours plus tard, celui-ci (il n’est pas daté), à la suite du précédent :

Unhandled exception in thread started by <bound method _Timer.__bootstrap of <_Timer(Thread-3810954, stopped daemon 1868559456)>>
Traceback (most recent call last):
File "/usr/lib/python2.7/threading.py", line 774, in __bootstrap
self.__bootstrap_inner()
File "/usr/lib/python2.7/threading.py", line 789, in __bootstrap_inner
del _limbo[self]
KeyError: <_Timer(Thread-3810954, stopped daemon 1868559456)>

Pour ta réponse :

Pour information :

J’ai signalé ce fil à l’équipe aujourd’hui même

Mips · Juin 16, 2020, 8:37

Veux-tu dire que

12 jours plus tard tu as eu le Critical error on send_changes_async threads etc suivi directement de Unhandled exception in thread started by etc?
ou
12 jours plus tard tu as eu le deuxième cas Unhandled exception in thread started by etc mais sans avoir le premier?

Si c’est la réponse 1, on pourrait supposer tu es tombé dans un cas ou lors de la deuxième tentative dans le bloc except, ligne 86, il y a eu de nouveau le problème mais comme on est déjà dans un bloc except ca a fini en Unhandled exception (logique).
Si c’est réponse 2, alors je ne comprend pas (encore) ce cas.

Fabrice · Juin 16, 2020, 9:16

En fait, j’ai eu les messages dans l’ordre indiqué :

24 heures après mon démarrage (mise à jour du Pi) :

[2020-06-03 00:34:47][ERROR] : Critical error on  send_changes_async threads can only be started once
Unhandled exception in thread started by <bound method _Timer.__bootstrap of <_Timer(Thread-45204, stopped daemon 1879041120)>>
Traceback (most recent call last):
File "/usr/lib/python2.7/threading.py", line 774, in __bootstrap
self.__bootstrap_inner()
File "/usr/lib/python2.7/threading.py", line 789, in __bootstrap_inner
del _limbo[self]
KeyError: <_Timer(Thread-45204, stopped daemon 1879041120)>

12 jours plus tard, j’ai cela à la suite (sans date ni Critical error…)

Unhandled exception in thread started by <bound method _Timer.__bootstrap of <_Timer(Thread-3810954, stopped daemon 1868559456)>>
Traceback (most recent call last):
File "/usr/lib/python2.7/threading.py", line 774, in __bootstrap
self.__bootstrap_inner()
File "/usr/lib/python2.7/threading.py", line 789, in __bootstrap_inner
del _limbo[self]
KeyError: <_Timer(Thread-3810954, stopped daemon 1868559456)>

Au final, dans la log c’est comme cela :

[2020-06-03 00:34:47][ERROR] : Critical error on  send_changes_async threads can only be started once
Unhandled exception in thread started by <bound method _Timer.__bootstrap of <_Timer(Thread-45204, stopped daemon 1879041120)>>
Traceback (most recent call last):
File "/usr/lib/python2.7/threading.py", line 774, in __bootstrap
self.__bootstrap_inner()
File "/usr/lib/python2.7/threading.py", line 789, in __bootstrap_inner
del _limbo[self]
KeyError: <_Timer(Thread-45204, stopped daemon 1879041120)>
Unhandled exception in thread started by <bound method _Timer.__bootstrap of <_Timer(Thread-3810954, stopped daemon 1868559456)>>
Traceback (most recent call last):
File "/usr/lib/python2.7/threading.py", line 774, in __bootstrap
self.__bootstrap_inner()
File "/usr/lib/python2.7/threading.py", line 789, in __bootstrap_inner
del _limbo[self]
KeyError: <_Timer(Thread-3810954, stopped daemon 1868559456)>

Mips · Juin 16, 2020, 9:26

Question con: comment tu sais que c’est 12 jours après alors?

kristobal · Juin 17, 2020, 6:24

Bonjour @Mips
Même si je comprend pas tout j’ai pris la peine de te lire
et donc je n’ai pas le message dont tu parles Issue with the async timer reseting
Merci pour les recherches de solutions