Décrochage et comportement étrange Bluetooth

Abreiv · Février 2, 2021, 1:57

Bonjour à tous,

J’utilise le plugin Blea dans le cadre de détection de présence, avec des Nut Nutale.
Au niveau de mon installation, j’ai un Proxmox avec une VM Jeedom 4.1.19 et une VM Antenne sous Debian, le tout sur un NUC. J’ai sur cette VM Antenne fait un passthrough de la carte Bluetooth vers la VM, afin d’en faire une Antenne Bluetooth dans Blea (j’ai vu à plusieurs reprise cette recommandation, plutôt que de laisser le service sur le Core.
Mon Blea est en version stable 2020-11-21 01:01:09.

Actuellement j’ai régulièrement des décrochages du Bluetooth mais qui sont très spécifique, car :

Le Nut est considéré comme présent 98% du temps quand il doit l’être, le décrochage à lieu une fraction de seconde, c’est à dire que le Nut est considéré comme absent « Not seen » à 14h25:40 et il est à nouveau considéré comme « seen » à 14h25:48. Mais cela enclenche quand même les scénario forcément
J’ai deux Nut, il arrive parfois que les deux décroche en même temps, pareil une fraction de seconde, mais c’est pas systématiquement en même temps. Il y a souvent une forme de « récurrence » quand ils décroche en même temps, souvent la nuit, 3 nuit d’affilé à 01h39, puis deux nuit d’affilé à 01h39 + 04h22, puis par la suite deux nuit d’affilé à 04h22 uniquement. Puis ça change, mais on peu quand même constaté un certain côté cyclique.
Ça décroche minimum une fois par jour (souvent la nuit, entre minuit et 2h) fréquemment plusieurs fois par jour (3 à 6 fois) dont certain décrochage des deux Nut, certain individuels.
Je n’ai pas constaté de Cron spécifique sur les horaires défini, ni de backup Proxmox ou autre
J’ai changé les piles des Nut, même constat
J’ai changé les valeur de durée entre deux scan, et le nombre d’itération avant de considéré comme acescent (donc la durée total avant timeout), cela n’a eu aucun effet. Le dysfonctionnement coïncide d’ailleurs car le Nut se raccroche instantanément après avoir décroché.

J’envisage également de tester avec une autre antenne physique que le chip intégré dans le NUC (car je peux émettre certain doute dessus, même si ça a eu marché plusieurs semaines sans soucis), je pensais prendre une Sena UD100 mais celle-ci est actuellement indisponible partout.
Existe-il un autre modèle de référence ? Éventuellement plus moderne ?

Avez-vous déjà fait face à ce type de dysfonctionnement et avez vous des solutions ?
Sinon avez vous des pistes ou des recommandations ?

Je suis désolé, je n’ai pas mes logs précis car j’ai oublié de les copier et ils ont une durée de conservation très courte en mode debug. Le log de l’antenne ressemble très fortement à ça :

[2019-08-04 09:57:26.345][DEBUG] : Send to jeedom : {'devices': {'E9:06:C5:77:8D:A6': {'type': 'default', 'rssi': -94, 'source': 'local', 'name': 'default', 'id': 'E9:06:C5:77:8D:A6', 'present': 1}}}
[2019-08-04 09:59:23.912][INFO] : Not SEEEEEEEEEN------ since 116s E9:06:C5:77:8D:A6
[2019-08-04 09:59:24.202][DEBUG] : Send to jeedom : {'devices': {'E9:06:C5:77:8D:A6': {'present': 0, 'rssi': -200, 'id': 'E9:06:C5:77:8D:A6', 'source': 'local'}}}
[2019-08-04 09:59:33.878][DEBUG] : SCANNER------[(1, 'Flags', '06'), (255, 'Manufacturer', '570100feb3f6f575fe3e924677bc6c0c944b8002e906c5778da6')] True random e9:06:c5:77:8d:a6
[2019-08-04 09:59:33.881][DEBUG] : SCANNER------It's a unknown packet and I known this device so I send e9:06:c5:77:8d:a6
[2019-08-04 09:59:33.882][INFO] : RE SEEEEEEEEEN------E9:06:C5:77:8D:A6 || {'FF:FF:C5:16:46:70': {'present': 0}, 'C4:7C:8D:6B:04:E8': {'present': 1, 'lastseen': 1564905570}, 'C4:7C:8D:6A:48:52': {'present': 1, 'lastseen': 1564905571}, 'C0:39:F8:F5:20:CB': {'present': 0, 'lastseen': 1564903311}, 'E9:06:C5:77:8D:A6': {'present': 1, 'lastseen': 1564905573}, 'C4:7C:8D:6B:1C:82': {'present': 0}}
[2019-08-04 09:59:33.883][DEBUG] : {'type': 'default', 'rssi': -82, 'source': 'local', 'name': 'default', 'id': 'E9:06:C5:77:8D:A6', 'present': 1}

Je fournirais mes propre log au prochain décrochage si je suis assez rapide pour les récupérer. J’ajouterais à cette échange.
Sur le core, rien de spécifique au moment du décrochage, essentiellement des logs d’activité Heartbeat.

Merci de votre aide

sebfar · Février 2, 2021, 2:00

Salut
Moi j’utilise les paramètres de refresh pour considérer que ce n’est pas un faux positif si le nut n’est pas détecté au bout de 10 mn

Fabrice · Février 2, 2021, 6:48

Bonsoir,

Vous n’avez pas le plugin Phone Detection ?

jerome6994 · Février 2, 2021, 7:21

C’est la première chose à quoi j’ai pensé tient tient c’est bizarre

Mips · Février 2, 2021, 8:11

Bonjour,
Pas de backup des vm par proxmox à ce moment ?

Abreiv · Février 2, 2021, 8:32

Alors pour répondre au questions :
J’ai essayé d’augmenter les seuils mais les décrochage perdure, je vais appliquer de la même manière des seuils très élevé voir si j’ai une évolution.

Je n’ai pas le plugin phone detection, j’avais essayé et effectivement j’avais plein de décrochage avec l’utilisation de celui-ci en parallèle.

Pour les backup de VM ça ne correspond pas aux horaires, en tout cas sur l’ensemble des décrochage j’en ai 90% hors plage de backup

Merci déjà pour le temps pris à étudier ma demande

Abreiv · Février 8, 2021, 3:59

Bonjour,

Je viens apporter un peu plus d’éléments à mes précédent postes.
Depuis quelques jours j’ai une meilleur stabilité, en conservent un décrochage uniquement là nuit à 01h36.
Dans les logs de Blea, sur Jeedom, je constate qu’il lance un restart de l’antenne à ce moment là, visiblement de lui même. Je ne vois pas de configuration spécifique à ce sujet dans le plugin.
Voici le log :

[2021-02-08 01:33:32][INFO] : This is a heartbeat from antenna Antenne-Debian
[2021-02-08 01:34:28][INFO] : This is a heartbeat from antenna Antenne-Debian
[2021-02-08 01:35:24][INFO] : This is a heartbeat from antenna Antenne-Debian
[2021-02-08 01:36:06][INFO] : Restarting daemon on remote Antenne-Debian
[2021-02-08 01:36:06][INFO] : Lancement du démon distant
[2021-02-08 01:36:06][INFO] : Arret du démon distant
[2021-02-08 01:36:06][INFO] : Commande par SSH fuser -k 55008/tcp >> /dev/null 2>&1 & sur ip.de.mon.antenne

Je n’ai malheureusement pas les logs de l’antenne, en mode debug celle-ci fait une rotation très rapidement.
Je vais mettre sur l’antenne une action planifiée pour copier le log à 01h37 afin de conserver les infos. Je verrais si j’en apprend plus.

Vous avez une idée sur le restart automatique journalier du service Blea sur une antenne ?

Merci

Mips · Février 8, 2021, 11:21

Il faudrait le log en debug pour voir s’il y a plus d’info

Fabrice · Février 9, 2021, 7:48

Bonjour,

Regardez aussi dans le moteur des tâches, si vous n’avez pas quelque chose qui s’effectue à cette heure là.
Regardez la tâche backup surtout.

Abreiv · Février 9, 2021, 9:53

Bonjour,

Merci pour vos réponses.
Effectivement, j’avais regardé côté cron du système sans succès. En revanche j’ai était voir niveau tache planifié de Jeedom, et il s’agit bien de l’heure ou s’effectue la cronDaily !
Je n’ai pas encore réussi à trouver ce que contenait cette cron mais les heures coïncident.

Au sujet des logs de l’antenne, j’ai pu les extraire à 01h37, ils contiennent des informations qui concorde également 01h36, un ordre du core pour stop et start le service :

[2021-02-09 01:36:05.929][DEBUG] : Client connected to [ip.du.core.jeedom:53142]
[2021-02-09 01:36:05.929][DEBUG] : Message read from socket: b'{"apikey":"MacleAPI","cmd":"stop"}'
[2021-02-09 01:36:05.929][DEBUG] : Client disconnected from [ip.du.core.jeedom:53142]
[2021-02-09 01:36:06.074][DEBUG] : SOCKET-READ------Message received in socket JEEDOM_SOCKET_MESSAGE
[2021-02-09 01:36:06.075][DEBUG] : SOCKET-READ------Received command from jeedom : stop
[2021-02-09 01:36:06.075][INFO] : SOCKET-READ------Arret du demon sur demande socket
[2021-02-09 01:36:06.076][DEBUG] : Send to jeedom :  {'learn_mode': 0, 'source': 'Antenne-Debian'}
[2021-02-09 01:36:06.078][DEBUG] : Starting new HTTP connection (1): ip.du.core.jeedom:80
[2021-02-09 01:36:06.084][DEBUG] : http://ip.du.core.jeedom:80 "POST /plugins/blea/core/php/jeeBlea.php?apikey=MacleAPI HTTP/1.1" 200 0
[2021-02-09 01:36:11.374][INFO] : GLOBAL------Start blead
[2021-02-09 01:36:11.374][INFO] : GLOBAL------Log level : debug
[2021-02-09 01:36:11.374][INFO] : GLOBAL------Socket port : 55008
ETC..

Mips · Février 11, 2021, 6:28

C’est dommage de couper le log avant, c’était probablement le plus intéressant.
Avoir le log de restart alors qu’on sait qu’il a eu lieu ne sert à rien…

Abreiv · Février 12, 2021, 5:37

Bonjour,

Dans ce cas j’ajoute tout le log présent au moment de la copie.
Je l’ajoute en pièce jointe : blea-log-01h37.log (64,6 Ko)

J’étais allé au plus direct car il semble que ce soit la cron de 01h37 qui initie le restart du service.
Savez-vous comment analyser ce qui est enclenché par cette tache automatique ?

Merci pour votre aide