Zigbee2mqtt - MQTT2 Client Buffer

[ake]

Hallo zusammen,

ich habe seit einer Weile ein Problem mit der zigbee2mqtt Kommunikation und suche vergeblich nach einer Lösung.
Ich habe einen CC2652RB stick (USB-A) als Koordinator für mein Zigbee Netzwerk. Auf dem Rpi4 läuft zigbee2mqtt. Im fhem ist die Einbindung auch gut gelungen. Ich habe im Garten mehrere Paulmann GU10 LED Lampen und 3 Phillips RGB Globes die mir Probleme bereiten. Immer mal wieder wenn ich diese steuern möchte, wird der Mqtt2 Client Buffer voll, enthält irgendeinen Müll und dann funktioniert gar nichts mehr in der Kommunikation mit FHEM, jedoch kann ich immer noch direkt über die zigbee2mqtt UI steuern. Das Problem bleibt bestehend solange dieser BUF etwas enthält. Wenn er wieder leer ist, funktioniert MQTT in FHEM wieder. Manchmal erholt sich der buffer von alleine innerhalb paar Stunden, manchmal gar nicht (ich habe sogar eine Woche laufen lassen). Die einzige Lösung ist dann ein restart von dem rpi. Ein restart vom zigbee2mqtt service hilft nicht.
Ich habe einen Screenshot angehängt.

Meine Konkrete Frage wäre: Woran liegt das? Gibt es eine Optionen die ich übersehen habe und welche das verhindern kann? Bin ich die einzige die das Problem hat? Ich habe auch versucht den buffer zu löschen (ja, ich weiß, ist ein Internal Val und man macht das nicht, ich wollte aber alles probieren), das hilft nicht.
Eure Hilfe damit wäre sehr geschätzt, ich drehe langsam durch...

[Beta-User]

Vorab mal willkommen im FHEM-Forum!

BUF enthält nach meinem Verständnis einen "Zwischenstand" der bereits empfangenen Daten, und wird gefüllt, bis die angekündigte Länge an Daten da ist. Anscheinend kommt da irgendwas dazwischen, sei es, dass der MQTT-Server, den du einsetzt, zwischendurch abbricht, sei es, dass FHEM irgendwas verpaßt (ist der Pi sehr ausgelastet und fängt an zu swappen?), sei es, dass die Ankündigung falsch ist oder das Encoding irgendwas zerhaut (da kann vielleicht Rudi was zu sagen).

Na ja, jedenfalls sollte es mit einem einfachen "connect" (am MQTT2_CLIENT) möglich sein, die Verbindung zurückzusetzen. Hattest du das auch versucht?

Ansonsten ist es ohne nähere Info zu allen möglichen vermutlich ziemliche Kaffeesatzleserei... Die meisten werden wohl MQTT2_SERVER im Einsatz haben, und/oder ggf. die subscriptions eingeschränkt, weniger traffic auf dem mosquitto (?), ...

Text-Infos bitte künftig in Code-Tags einpacken.

[rudolfkoenig]

Was fuer ein MQTT Server wird verwendet?

[ake]

Vielen Dank für eure Antworten.

Ich verwende keine FHEM Server Instanz. Hier mein Broker:

Code Auswählen Erweitern


pi@rpi4:~ $ sudo systemctl status mosquitto
● mosquitto.service - Mosquitto MQTT v3.1/v3.1.1 Broker
   Loaded: loaded (/lib/systemd/system/mosquitto.service; enabled; vendor preset: enabled)
   Active: active (running) since Wed 2022-07-20 21:28:52 CEST; 21h ago
     Docs: man:mosquitto.conf(5)
           man:mosquitto(8)
Main PID: 444 (mosquitto)
    Tasks: 1 (limit: 4915)
   Memory: 4.3M
   CGroup: /system.slice/mosquitto.service
           └─444 /usr/sbin/mosquitto -c /etc/mosquitto/mosquitto.conf

Jul 20 21:28:52 rpi4 systemd[1]: Starting Mosquitto MQTT v3.1/v3.1.1 Broker...
Jul 20 21:28:52 rpi4 systemd[1]: Started Mosquitto MQTT v3.1/v3.1.1 Broker.


[rudolfkoenig]

Ich habe einen Test aufgesetzt, mit MQTT2_CLIENT (m2c) und mosquitto auf dem gleichen Rechner.
Ich habe erst "attr m2c rawEvents .*" gesetzt, danach

Code Auswählen Erweitern

{ for my $i (1..50000) { fhem("set m2c publish a/b HalloThere") } }
ausgefuehrt.
Wegen der Voreinstellung ist die m2c subscription #, d.h. FHEM kriegt alle gesendeten Daten zurueck.

Die Nachrichten waren nach 4 Sekunden weg, das eventCount Internal stand auf 50001.
Alle zurueckgeschicken Nachrichten zu verdauen (=> eventCount 100001) hat weitere 25 Sekunden gedauert.
Waehrend dieser Zeit enthielt BUF mal weniger, mal mehr "Muell", zum Schluss war BUF aber leer.

Will sagen: temproraer, bei hoher FHEM-Last, kann BUF Daten enthalten.
Wenn BUF nie leer wird, dann ist irgendwo ein Uebertragungsproblem: entweder gehen Daten vorloren, oder FHEM und Mosquitto sind nicht einig uebers Protokoll.
In diesem Fall haette ich gerne was zum Nachstellen.

[ake]

Hallo Rudi,

was wäre dann noch hilfreich in meinem Fall mit dem MQTT BUF Problem? Was soll ich dir noch zur Verfügung stellen? Wir können von mir aus auch eine Remote - Session machen, wo du dich auf meinem Rechner einloggst. Ich bin da ganz offen, wenn du mir helfen kannst. Vielleicht liegt es auch an mir, vielleicht habe ich etwas falsches Konfiguriert, ich sehe es aber nicht.

[rudolfkoenig]

Ein gefuelltes/kaputtes BUF hat nichts direkt mit Steuerungsproblemen (== MQTT publish) zu tun, Senden ist unabhaengig vom BUF.
BUF wird auch geleert, wenn die Verbindung neu aufgemacht wird. Die Voreinstellung fuer keepalive ist  30, d.h. nach 45 Sekunden sollte FHEM ein Kommunikationsproblem mit mosquitto entdecken, und die Verbindung neu oeffnen.

Zunaechst muss ich ueber ein paar Grundlagen klar werden:
#1 stimmt, dass FHEM, mosquitto und zigbee2mqtt auf dem gleichen Rechner laufen?
#2 gibt es im FHEM-Log vom MQTT2_CLIENT gemeldete Fehler wie disconnected, reappeared, NO PINGRESP, etc.
#3 wie ist die Auslastung des Rechners, insb. im Problemfall. Mich interessiert, was top insgesamt (oben: us/sy/ni/id/wa) und fuer FHEM (die perl Zeile: %CPU, %MEM) anzeigt.

[ake]

#1 - Ja. das stimmt, alles läuft auf einem pi4
#2 - Ja, habe ich einen anderen MQTT2_CLIENT der immer mal wieder zwischen disconnected und reappeared wechselt.
#3 -

Code Auswählen Erweitern


top - 21:45:12 up 23:35,  3 users,  load average: 0.00, 0.02, 0.03
Tasks: 135 total,   1 running, 134 sleeping,   0 stopped,   0 zombie
%Cpu(s):  0.3 us,  0.2 sy,  0.0 ni, 99.4 id,  0.0 wa,  0.0 hi,  0.1 si,  0.0 st
MiB Mem :   3906.0 total,   3117.1 free,    333.5 used,    455.4 buff/cache
MiB Swap:    100.0 total,    100.0 free,      0.0 used.   3454.0 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
  595 fhem      20   0  112560 103248   7700 S   1.3   2.6  66:52.28 perl
    1 root      20   0   33732   8016   6396 S   0.0   0.2   0:02.85 systemd
    2 root      20   0       0      0      0 S   0.0   0.0   0:00.06 kthreadd
    3 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 rcu_gp
    4 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 rcu_par_gp
    8 root       0 -20       0      0      0 I   0.0   0.0   0:00.00 mm_percpu_wq



[rudolfkoenig]

#2 - Ja, habe ich einen anderen MQTT2_CLIENT der immer mal wieder zwischen disconnected und reappeared wechselt.

Kannst Du bitte _alle_ MQTT2_CLIENT Definitionen zeigen?
Wurde dieses top "Screenshot" im Problemfall gemacht. d.h. BUF war gerade nicht leer?

[ake]

Ich bin bis Ende August im Urlaub, sobald ich wieder daheim bin, werde ich die Infos posten. Danke erstmal!

[ake]

Hallo rudolfkoenig,

nun habe ich nach meinem Urlaub weiter versucht das Problem einzugrenzen.
Ich habe die Konfiguration auf dem Minimum reduziert und die zur Zeit unnötige Clients gelöscht.
Zur Zeit habe ich:

1. Der erste Client (der mit dem Problem, siehe BUF unten) der für die zigbee2mqtt Kommunikation zuständig ist:

Code Auswählen Erweitern


Internals:
   BUF           
   DEF        127.0.0.1:1883
   DeviceName 127.0.0.1:1883
   FD         118
   FUUID      60d8db5a-f33f-3078-bab0-3c93efb4dbade208
   NAME       MQTT.Client
   NR         308
   PARTIAL   
   STATE      opened
   TYPE       MQTT2_CLIENT
   WBCallback
   clientId   MQTT.Client
   connecting 2
   lastMsgTime 1665140525.72337
   nextOpenDelay 5
   READINGS:
     2022-10-07 13:03:37   state           opened
Attributes:
   autocreate simple
   devStateIcon .*active:none:disconnect .*disconnected:none:connect
   keepaliveTimeout 30
   room       MQTT2_CLIENT


2. Der zweite Client:

Code Auswählen Erweitern


Internals:
   BUF       
   DEF        a1optpg91s0ydf-ats.iot.eu-west-1.amazonaws.com:8883
   DeviceName a1optpg91s0ydf-ats.iot.eu-west-1.amazonaws.com:8883
   FD         119
   FUUID      627bcbfe-f33f-3078-29b1-14c2fc5e49a933bc
   NAME       MQTT.Worx
   NR         492
   PARTIAL   
   SSL        1
   STATE      opened
   TYPE       MQTT2_CLIENT
   WBCallback
   clientId   android-<client-ID>
   lastMsgTime 1665140644.8962
   nextOpenDelay 5
   READINGS:
     2022-09-30 14:01:44   state           opened
   sslargs:
     SSL_cert_file aws.cer
     SSL_key_file aws.key
     SSL_use_cert 1
     SSL_version TLSv12
Attributes:
   SSL        1
   autocreate simple
   clientId   <client-ID>
   keepaliveTimeout 600
   mqttVersion 3.1.1
   msgAfterConnect PRM100/98D86/commandIn {}
   room       3.0 Garden,MQTT2_CLIENT,MQTT2_DEVICE
   sslargs    SSL_version:TLSv12 SSL_cert_file:aws.cer SSL_key_file:aws.key SSL_use_cert:1
   subscriptions PRM100/98D86/commandOut


Der erste Client befindet sich wieder in einem Status wo er nicht mehr Kommunikationsfähig ist, weil der BUF nicht geleert wird. Das Problem tritt auf immer im Verbindung mit zigbee2mqtt. Entweder wenn ein neues zigbee Device angelernt wird, oder nach paar Tage wo die zigbee2mqtt Kommunikation gut läuft.

Der zweite Client funktioniert zuverlässig, ist immer "open".

[rudolfkoenig]

Bei kaputten Daten (und damit BUF laenger nicht leer) wird die Verbindung spaetestens nach 2*keepaliveTimeout neu aufgebaut, das habe ich gerade mit einem preparierten MQTT2_SERVER als Gegenseite getestet.

Ich habe keine Hypothese, was die Symptome erklaert: BUF fuer laenger als eine Minute nicht leer, FHEM reagiert, CPU nicht belegt, kein reconnect Meldung im Log fuer diese Verbindung.

Mir wuerde nur ein "attr MQTT2.Client verbose 5" Log weiterhelfen, von der Zeit wo es funktioniert, bis zum Kaputtzustand.

[ake]

Alles klar, mache ich. Es dauert aber immer einige Tage bis er wieder in dem Zustand gelangt.

[ake]

Es ging schnell.
Hier die Datei

[rudolfkoenig]

Ich gehe davon aus, dass das angehaengte Log gefiltert ist, weil ich keine Zeilen mit DevIO sehe.

Zwischen 14:04 und 19:52 schaut alles normal aus.

Auf dem PINGREQ von FHEM um 19:52:06 liefert mosquitto keine Antwort (PINGRESP), was FHEM zum DISCONNECT veranlasst.
Danach geht alles schief, weil auf die CONNECT Nachricht von FHEM mosquitto nicht antwortet (erwartet wird CONNACK), was die im CONNECT versprochene keepAlives seitens FHEM verhindert, was wiederum mosquitto zum Beenden der Verbindung noetigt. FHEM versucht es erneut, mit dem gleichen Ergebnis (kein CONNACK, usw).

So geht das weiter bis 20:16:12, dann kommt immer wieder Muell ins Puffer.
Ich kann darauf keinen Reim machen, soweit ich sehe wird BUF bei jedem reconnect neu initialisert.

Ich habe in der angehaengten Version etwas mehr Debugging eingebaut, es waere parktisch, wenn ich ein vergleichbares Log mit dieser Version sehen koennte.

Hab vergessen zu fragen: ist FHEM aktuell?