MQTT2_CLIENT Probleme

Begonnen von rudolfkoenig, 07 November 2018, 21:12:15

Vorheriges Thema - Nächstes Thema

HomeAlone

Zitat von: rudolfkoenig am 04 Dezember 2018, 11:23:51
Netter Versuch, aber set publish in MQTT2_CLIENT interpretiert {} nicht als Perl Ausdruck, sondern sendet es unveraendert an den Server.
Sowas ist mW auch nirgendwo dokumentiert, wenn doch, bitte sagen.
Nein, hast Du nirgends geschrieben, aber ich dachte Versuch macht kluch... ;)

Zitat von: rudolfkoenig am 04 Dezember 2018, 11:23:51

Ich habe versucht die Endlosschleife nachzustellen:
- mosquitto mit SSL und aktivierten Benutzer/Passwort gestartet
- MQTT2_CLIENT passend konfiguriert.
- geprueft, dass beim falschen Passwort "Connection refused, not authorized" kommt, danach korrektes Passwort wieder gesetzt
- das erwaehnte set abgesetzt.

Mosquitto liefert das topic zurueck, wg. autocreate erweitert FHEM das angelegte MQTT2_DEVICE, das ein reading mit dem Namen test und mit dem Wert {toJSON({ 'state' => 'OFF'})} kriegt.
=> Works as designed.

Bin bereit weiter zu debuggen, wenn ich das Problem nachstellen kann.
Aktuell läuft es bei mir stabil, habe seit Deinem Posting keine Abstürze mehr gehabt. Ich habe bei mir auch kein MQTT2_DEVICE in der Config. Werde mir zu Testzwecken aber eines anlegen, da ich es vermutlich spätenstens, wenn ich nicht nur publishen sondern auch subscriben will benötigen werde.

Zitat von: rudolfkoenig am 04 Dezember 2018, 11:23:51
Btw: die Perl Auswertung kann man mittels den global (d.h. fuer alle sets) verfuegbaren Set-Magic errreichen:set mosquitolocal publish fhempub/test {( toJSON({'state'=>'OFF'}) )}

Man achte auf {(...)}
Vielen Dank, habe ich ausprobiert und - oh Wunder ;) - es funktioniert. "set magic" kannte ich bisher noch nicht - muss ich mir mal genauer ansehen. Für interessierte Leser zum Ersparen der Googleanfrage: https://wiki.fhem.de/wiki/Set_magic

Noch mal vielen Dank für Deinen Einsatz, Rudi!

OdfFhem

Im Produktiv-System nutze ich derzeit folgende (schon etwas ältere) MQTT2-Version

00_MQTT2_CLIENT.pm    17867 2018-11-29 09:55:51Z rudolfkoenig
10_MQTT2_DEVICE.pm    17832 2018-11-24 15:24:30Z rudolfkoenig

und habe damit keine nennenswerten Probleme.

Nun wollte ich mal im Test-System mit dem aktuell verteilten MQTT2-Stand komplett neu aufsetzen.


Dabei stoße ich schon sehr früh auf folgende (ernsten) Probleme:


Ich nutze MQTT2_CLIENT mit externem mosquitto-Server. Bis man das Passwort gesetzt hat, schaltet der Status vom MQTT2_CLIENT-Device in rasantem Tempo zwischen opened bzw. disconnected hin und her und "müllt" dabei munter das Logfile zu.
Ein wirklich sehr kleiner Auszug aus dem Logfile

2018.12.09 13:27:43.932 3: Opening myMqttClient device raspberrypi:1883
2018.12.09 13:27:43.946 3: myMqttClient device opened
2018.12.09 13:27:43.968 1: raspberrypi:1883 disconnected, waiting to reappear (myMqttClient)
2018.12.09 13:27:43.976 1: raspberrypi:1883 reappeared (myMqttClient)
2018.12.09 13:27:43.980 1: raspberrypi:1883 disconnected, waiting to reappear (myMqttClient)
2018.12.09 13:27:43.987 1: raspberrypi:1883 reappeared (myMqttClient)
2018.12.09 13:27:43.991 1: myMqttClient: Connection refused, not authorized
2018.12.09 13:27:43.993 1: raspberrypi:1883 disconnected, waiting to reappear (myMqttClient)
2018.12.09 13:27:44.190 1: raspberrypi:1883 reappeared (myMqttClient)
.
.
.



Das zum CLIENT gehörige MQTT2-Device wird automatisch angelegt, heißt aber aus meiner Sicht falsch - MQTT2_my_qtt_lient statt MQTT2_myMqttClient.

autocreate: define MQTT2_my_qtt_lient MQTT2_DEVICE myMqttClient



Dieses Problem setzt sich dann auch nach dem Setzen von bridgeRegexp für die automatisch angelegten, eigentlichen MQTT2_DEVICEs fort.

autocreate: define MQTT2_zigbee_dimmer_witch1 MQTT2_DEVICE zigbee_dimmerSwitch1



Noch ein Hinweis zum bridgeRegexp: Verwendet man die 0x-Variante für zigbee2mqtt, darf man keine friendly_names verwenden.

rudolfkoenig

ZitatDabei stoße ich schon sehr früh auf folgende (ernsten) Probleme:
Unter ernst verstehe ich sowas wie "funktioniert gar nicht".

ZitatBis man das Passwort gesetzt hat, schaltet der Status vom MQTT2_CLIENT-Device in rasantem Tempo zwischen opened bzw. disconnected hin und her und "müllt" dabei munter das Logfile zu.
Interessant, bei mir werden nur alle 3 Sekunden Meldungen geschrieben. Laeuft dein FHEM auf Windows?
Ab sofort wird bei CONNACK mit Fehler das authError Internal gesetzt, was ein reconnect verhindert.
Dieses Internal wird entfernt, wenn man "attr m2c username" oder "set m2c password" ausfuehrt oder FHEM neu startet.

ZitatDas zum CLIENT gehörige MQTT2-Device wird automatisch angelegt, heißt aber aus meiner Sicht falsch - MQTT2_my_qtt_lient statt MQTT2_myMqttClient.
Danke fuer den Hinweis, ich habe es gefixt.

ZitatNoch ein Hinweis zum bridgeRegexp: Verwendet man die 0x-Variante für zigbee2mqtt, darf man keine friendly_names verwenden.
Das habe ich nicht verstanden, bitte anders formulieren, oder ein konkretes Beispiel anhaengen.

OdfFhem

Zitat
Unter ernst verstehe ich sowas wie "funktioniert gar nicht".
Daher hatte ich "ernst" eingeklammert und bezog sich eigentlich auch mehr auf die autocreate-Funktionalität; im Produktiv-System z.B. wären ja vermutlich lauter neue, unkonfigurierte Devices angelegt worden und die alten, bereits konfigurierten Devices würden nicht mehr aktualisiert - wären somit ohne Funktion.

Zitat
Laeuft dein FHEM auf Windows?
Nein - läuft unter Raspbian Stretch auf einem Raspberry Pi.

Zitat
Das habe ich nicht verstanden, bitte anders formulieren, oder ein konkretes Beispiel anhaengen.
Bei zigbee2mqtt wird jedes Gerät über eine eindeutige Hex-ID (z.B. 0x123456789) identifiziert. Dieser doch sehr technische Name kann durch die rename-Funktionalität mit einem etwas sprechenderen Namen (z.B. dimmerSwitch1) - dem friendly_name -  versehen werden. Macht man dies, werden die MQTT-Publish-Meldungen von zigbee2mqtt zukünftig unter dem friendly_name und nicht mehr unter der Hex-ID verbreitet, was unmittelbar Auswirkung auf bridgeRegexp, readingList, usw. hat.

Statt

zigbee2mqtt/0x123456789:.* { json2nameValue($EVENT) }

müsste das readingList-Attribut beim FHEM-Device dann so aussehen

zigbee2mqtt/dimmerSwitch1:.* { json2nameValue($EVENT) }


rudolfkoenig

ZitatDieser doch sehr technische Name kann durch die rename-Funktionalität mit einem etwas sprechenderen Namen (z.B. dimmerSwitch1) - dem friendly_name -  versehen werden. Macht man dies, werden die MQTT-Publish-Meldungen von zigbee2mqtt zukünftig unter dem friendly_name und nicht mehr unter der Hex-ID verbreitet, was unmittelbar Auswirkung auf bridgeRegexp, readingList, usw. hat.
Das Problem in diesem Fall ist einen Algorithmus zu finden, was den bridge vom Rest unterscheidet.
Wenn jemand eine Idee hat, bitte melden.

Beta-User

Eine Idee habe ich dazu nicht, (mal abgesehen davon, dass alle Statusmeldungen über "zigbee2mqtt/log" reinkommen, man also eine Art negativer Auslese machen könnte).
Aber in's Wiki kommt der deutliche Hinweis, dass man nach Möglichkeit die Devices an der Stelle (friendly name) entweder unbearbeitet lassen sollte oder eben ein "0x" voranstellen. M.E. ist es ausreichend, dass man in FHEM einen "sprechenden Namen" vergeben kann.
Wer unbedingt will (z.B., weil das für eine andere HA-Software erforderlich ist), kann immer noch die bridgeRegexp erweitern; da sind ja auch mehrere Einträge zulässig...
Server: HP-elitedesk@Debian 12, aktuelles FHEM@ConfigDB | CUL_HM (VCCU) | MQTT2: MiLight@ESP-GW, BT@OpenMQTTGw | MySensors: seriell, v.a. 2.3.1@RS485 | ZWave | ZigBee@deCONZ | SIGNALduino | MapleCUN | RHASSPY
svn: u.a MySensors, Weekday-&RandomTimer, Twilight,  div. attrTemplate-files

Wallmeier

Ich hatte heute wieder die Situation, dass sich die Logzeilen "127.0.0.1:1883 reappeared (mqtt2)" und "127.0.0.1:1883 disconnected, waiting to reappear (mqtt2)" immer wieder abgewechselt haben. Nachdem ich Verbose für mqtt2 auf 5 gesetzt habe, bin ich noch nicht weiter gekommen und habe daraufhin noch einen tcpdump gemacht...


2019.01.03 12:16:37.697 1: 127.0.0.1:1883 disconnected, waiting to reappear (mqtt2)
2019.01.03 12:16:37.726 5: HttpUtils url=http://127.0.0.1:1883/
2019.01.03 12:16:37.728 4: IP: 127.0.0.1 -> 127.0.0.1
2019.01.03 12:16:37.732 1: 127.0.0.1:1883 reappeared (mqtt2)
2019.01.03 12:18:07.698 1: 127.0.0.1:1883 disconnected, waiting to reappear (mqtt2)


Der dazugehörige tcpdump ist angehängt...

Für mich sieht der dump so aus, dass der tcp-connect sauber durchgeführt wird, aber danach MQTT2_CLIENT keine CONNECT Nachricht an den Broker (mosquitto) schickt... Nach 90 Sekunden ohne Aktivität auf dem Socket schliesst dann Mosquitto den Socket...

Papaloewe

Ich habe den keepalive = 120 jetzt einmal testweise laufen und zumindest bis heute morgen lief es ohne Fehlermeldungen druch.
...mal abwarten.

rudolfkoenig

ZitatFür mich sieht der dump so aus, dass der tcp-connect sauber durchgeführt wird, aber danach MQTT2_CLIENT keine CONNECT Nachricht an den Broker (mosquitto) schickt...
Hier haette mich noch das "attr MQTT2_CLIENT verbose 5" Output interessiert.
Was fuer ein OS is das?
Eigentlich sendet MQTT2_CLIENT alle 30 Sekunden zusaetzlich auch ein PINGREQ, das haette man in deinem dump auch sehen sollen.
Die Daten gehen normalerweise ueber den select(write) Filter, damit FHEM sich wegen einem toten mosquitto nicht aufhaengt, evtl. haengt das Problem damit zusammen.

Ich habe jetzt eine Weile mit "kaputten" mosquitto (falsches password, SSL vs keins, usw) rumexperimentiert, und ich kann das Problem nur dann reproduzieren, falls mosquitto SSL erwartet, im FHEM das SSL Attribut aber nicht gesetzt ist.

Wallmeier

Verbose war bereits auf 5 gesetzt... Mehr als die Zeilen, die in meinem ersten Post zu dem Thema standen, gibt es schlicht nicht.

FHEM läuft bei mir auf Raspbian Strech (Raspberry Pi 3).

Ich gehe davon aus, dass der PINGREQ aber erst nach einem CONNECT überhaupt geschickt wird - und schon dieser fehlt.

Reproduzieren kann ich dieses zuverlässig in der Nacht - dort läuft um 3:00 von DbLog ein reduceLog, was dazu führt das fhem für ca. 92 Sekunden blockiert ist... Danach steht im Log ein "disconnected, waiting to reappear (mqtt2)" und es gibt die Endlosschleife aus "reappeared" und 90 Sekunden später "disconnected, waiting to reappear".

rudolfkoenig

Zitatdort läuft um 3:00 von DbLog ein reduceLog, was dazu führt das fhem für ca. 92 Sekunden blockiert ist
Das sollte vermieden, bzw. dringend gefixt werden.

Ich habe die Ursache mit einem { sleep(60) } nachgestellt, und mosquitto hat erwartungsgemaess die Verbindung zugemacht.
Danach gibg es aber bei mir weiter. Hier ist die Ausgabe  nach dem sleep:
Zitat2019.01.03 22:17:44 5: mc: keepalive 30
2019.01.03 22:17:44 5: mc: sending PINGREQ (192)(0)
2019.01.03 22:17:44 1: localhost:1883 disconnected, waiting to reappear (mc)
2019.01.03 22:17:49 5: HttpUtils url=https://localhost:1883/
2019.01.03 22:17:49 4: IP: localhost -> 127.0.0.1
2019.01.03 22:17:49 5: mc: sending CONNECT (16) (0)(6)MQIsdp(3)(194)(0)(30)(0)(2)mc(0)(4)user(0)(8)password
2019.01.03 22:17:49 5: SW: 102000064d514973647003c2001e00026d63000475736572000870617373776f7264
2019.01.03 22:17:49 1: localhost:1883 reappeared (mc)
2019.01.03 22:17:49 5: mc: received CONNACK (0)(0)
2019.01.03 22:17:49 5: mc: sending SUBSCRIBE (128)(6)(0)(4)(0)(1)#(0)
2019.01.03 22:17:49 5: mc: received PINGRESP
2019.01.03 22:17:49 5: mc: received SUBACK (0)(4)(0)
2019.01.03 22:18:19 5: mc: keepalive 30
2019.01.03 22:18:19 5: mc: sending PINGREQ (192)(0)...

Wallmeier

War bei dem Test die SVN Rev. 18127 schon aktiv?

rudolfkoenig

ZitatWar bei dem Test die SVN Rev. 18127 schon aktiv?
Ja, das wird aber dein Problem nicht loesen.
Die Aenderung in 18127 wuerde ein select-Problem umschiffen, soweit kommt es aber laut dem Log gar nicht.

Wallmeier

Ich hatte gestern Abend die Änderung von Rev. 18127 in meine Installation manuell reingepatcht gehabt - und heute Nacht hatte ich zwar auch wieder folgende Logzeilen

2019.01.04 03:01:36.668 1: 127.0.0.1:1883 disconnected, waiting to reappear (mqtt2)
2019.01.04 03:01:36.692 1: 127.0.0.1:1883 reappeared (mqtt2)

Aber diesmal mit dem großen Unterschied, dass es jetzt keine Endlosschleife geworden ist und die mqtt2-Instanz benutzbar ist  ;D

Reinhart

@Wallmeier

hast die eine SQLite Datenbank die du um 03:00 komprimierst bzw. alte Einträge löscht ( reduceLogNbl ) ?
Ich hatte den selben Fehler und die kamen eindeutig von dem Datenbank Job. Wenn ja, dann mach in der myDblog einen "configCheck" und befolge die Ratschläge, dann sind die Fehler im MQTT2_Client weg. Durch setzen des Attributes "asyncMode 1" ist das dann behoben.

2019.01.02 01:02:34 1: localhost:1883 disconnected, waiting to reappear (ebusMQTT)
2019.01.02 01:02:34 1: localhost:1883 reappeared (ebusMQTT)
2019.01.02 01:04:04 1: localhost:1883 disconnected, waiting to reappear (ebusMQTT)
2019.01.02 01:04:04 1: localhost:1883 reappeared (ebusMQTT)
2019.01.02 01:05:34 1: localhost:1883 disconnected, waiting to reappear (ebusMQTT)

das waren meine Fehlermeldungen im MQTT2_Client

2019.01.02 01:00:00 3: DbLog myDbLog -> Deletion of records older than 30 days in database /opt/fhem/fhem.db requested
und das der Auslöser wenn "asyncMode" nicht "1" ist.

LG
Reinhart

FHEM auf Raspy4 mit Bullseye + SSD, Homematic, ESP8266, ESP32, Sonoff, eBus, NanoCUL, MapleCUL, , MQTT2, Alexa