"Client FHEM disconnected due to malformed packet"

[Lothar64]

Hallo Beta-User,
vielen Dank für deine Hilfe, leider löst das nicht das Problem.
Ich habe heute abend herausgefunden wo diese 0x8a Nachrichten generiert werden. Da ich Perl nicht verstehe habe ich einfach mal ein paar Logs in den Code hinzugefügt, um das rauzufinden. Diese Nachtichten werden in 00_MQTT.pm in der sub Read generiert. Und zwar wenn eine Mesage MQTT_CONNACK empfangen wird. Ich habe zu Testzwecken einfach mal das DevIo_SimpleWrite auskommentiert. Dann gibt es keine Connection Abbrüche aufgrund "malformed packet" von Mosquitto mehr und ich kann Nachrichten in Fhem empfangen. Was nun nicht mehr funktioniert habe ich noch nicht herausgefunden. Warum die "falschen" Nachrichten generiert werden ist mir nciht klar.

Code: [Auswählen]

    MESSAGE_TYPE: {
      $message_type == MQTT_CONNACK and do {
        readingsSingleUpdate($hash,"connection","connected",1);
        onConnect($hash);
        GP_ForallClients($hash,\&client_start);
        GP_ForallClients($hash,\&notify_client_connected);
        foreach my $message_id (keys %{$hash->{messages}}) {
          my $msg = $hash->{messages}->{$message_id}->{message};
          $msg->{dup} = 1;
          # Commented out from Lothar64: DevIo_SimpleWrite($hash,$msg->bytes,undef);
        }
        last;
      };


[Beta-User]

CONNACK klingt irgendwie nach einer Bestätigung, dass die Verbindung da ist. Danach scheint das Modul alle zwischengespeicherten Messages (?) am Stück rauszuschicken, was ggf. der Gegenseite schlicht zu schnell ist...?

Eventuell würde es helfen, das ganze in eine rekursive Timer-Schleife zu packen, dann würde FHEM wenigstens nach jeder Nachricht kurz schauen, ob es noch was anderes zu tun gibt?

[Lothar64]

In dem tcpdump war aber keine ConnAck Message zu sehen, als Fhem angefangen hat diese 0x8a Messages zu senden. Das letzte ConnAck wurde etwa 500 ms vorher empfangen. Das war nach dem letzen Verbindungsabbruch und dem Neuconnecten. Dort wurde dann ein PINGREQ und PINGRESP ausgetauscht. Dann wurde angefangen die ganzen subscribe messages (0x82) auszutauschen. Also alles IO. Nur das nicht alle Subscribe Nachrichten raus gehen, sondern mitten drin dieses ConnAck" scheinbar empfangen" wird.
Woher bekommt das MQTT Modul nun diese ConAck Message, wenn es im TCP Dump nicht vorhanden ist und sendet korupte Nachrichten?

edit: falls jemand den kompletten TCP dump benötigt um das nachzuvollziehen, bitte Bescheid sagen. Ich glaube das ist zuviel um es hier zu posten oder?

[Beta-User]

Nun ja, was mich angeht: TCP-Dumps lesen ist nicht so mein Spezialgebiet; notfalls könnte man größere Datenmengen einfach anhängen.

Habe hexenmeister mal angeschrieben wegen dieses Threads hier und gehe mal davon aus, dass er sich bei Gelegenheit meldet.

Bezüglich der "Schein-Messages": Könnte es sein, dass das wegen des {dup}-flags von FHEM aus so erzeugt wird. In https://metacpan.org/release/BEANZ/Net-MQTT-1.163170/source/lib/Net/MQTT/Message.pm#L40 scheint irgendwas an Bits geschubst zu werden...? (ist auch in der 2014-er Version so drin).

Code: [Auswählen]

my $b = decode_byte($bytes, \$offset);
  $p{message_type} = ($b&0xf0) >> 4;
  $p{dup} = ($b&0x8)>>3;
  $p{qos} = ($b&0x6)>>1;
  $p{retain} = ($b&0x1);
Im Zweifel würde ich lieber erst mal die Zeile mit dem "dup"-Flag deaktivieren und die Messages als normale Messages raussenden; wenn ich hexenmeister in anderen Zusammenhängen richtig verstanden habe, sieht er den Vorteil des 00_MQTT-Moduls grade darin, dass es "sauber" Nachrichten puffert usw., so dass es mAn. kontraproduktiv ist, die Funktionalität komplett auszuschalten...

Kannst du in etwa sagen, wie viele gepufferte Messages da nach einem Connect in etwa gesendet werden, bis der Abbruch kommt?

Ansonsten ist der Code die "helle Freude", ich bin echt ratlos, was sich z.B. an Weisheit (oder Perl-Magie?!?) hinter dieser Konstruktion verbirgt (steht seit "Ewigkeiten" so drin):

Code: [Auswählen]

sub send_message($$$@) {
  my ($hash,%msg) = @_;Sowas macht es extrem schwer nachzuvollziehen, was eigentlich passieren soll.
(OK, zugegeben, die Aufrufe der Funktion im Code sind nachvollziehbar, aber das grade zu ziehen etwas aufwändiger).

[Lothar64]

Hallo Beta-User,
vielen Dank für deine Arbeit. Da das ganze scheinbar nicht einfach zu lösen ist, glaube ich das sinnvollste ist erstmal die Antwort von Hexenmeister abzuwarten. Ich hoffe er hat Zeit und Lust uns da weiter zu helfen. Ich könnte ihm alles was er benötigt zusenden.
Nach dem Verbindungsaufbau werden folgende Nachrichten ausgetauscht:
 CONNECT von Fhem
 CONNACK von Mosq.
 PINGREQ von Fhem
 PINGRESP von Mosq.
 22 mal
  SUBSCRIBE von Fhem
  SUBACK von Mosq.
 Dann kommt die kaputte Message

Ich bin hier zur Zeit auch erst mal am Ende meines Lateins. Da ich von Perl nichts verstehe, habe ich versucht logische Gemeinsamkeiten zu "C" zu finden und mittels Logs das ganze einzugrenzen. Ich weiß ja noch nicht einmal was da im Fehlerfall wirklich für Messages gesendet werden sollen, sind das 0x82 Nachrichten oder sind die 0x83 Nachrichten alter Datensalat in einem Buffer ...

Mit dem Auskommentieren von "DevIo_SimpleWrite($hash,$msg->bytes,undef);" in dem MQTT_CONNACK Zweig scheint (!) aber alles wieder zu funktionieren, soweit ich das bisher sehe. Das wäre also ein lokaler tempörarer Workaround für alle Betroffenen, bis es hoffentlich gefixt ist. Keine schöne Lösung, ich mag keine Workarounds, aber besser als gar keinen Fhem Server am Laufen zu haben.

[Beta-User]

Also...
Das läuft mAn. ab:
Das Modul verwaltet einen Puffer für Nachrichten, von denen es gerne eine Rückmeldung vom Server hätte. Nach einem reconnect werden diese Nachrichten "am Stück" rausgeschoben, allerdings mit einem "das ist eine Wiederholung"-flag ({dup}).
Du hast jetzt das Senden unterdrückt, was dazu führen kann, dass ggf. auch wichtige Nachrichten verloren gehen, (und die Queue uU. immer weiter vollläuft) statt das Risiko einzugehen, dass es eben doppelt/mehrfach gesendet wird.

Kannst du einfach mal testen, ob das Reconnect-Problem auch weg ist, wenn du zu Zeile vorher (_statt_ DevIo_SimpleWrite()) auskommentierst?
Die Schleife wäre dann:

Code: [Auswählen]

for my $message_id (keys %{$hash->{messages}}) {
          my $msg = $hash->{messages}->{$message_id}->{message};
          #$msg->{dup} = 1;
          DevIo_SimpleWrite($hash,$msg->bytes,undef);
        }
Falls das mit dem code-Auszug aus Message.pm sieht mir so aus, als würde da der originäre Message-Type einfach um drei (bit-) Stellen nach links verschoben, was beim unteren Nibble +8 bedeutet, aus 2 würde a (?)...

[Lothar64]

Danke auch hiermit gibt es keine reconnects  .
Alle Subscribe Nachrichen werden nun zwei mal gesendet, was Mosquitto akzeptiert. Das DUP Bit gibt es im MQTT ab 3.1.1 aber nur bei der Publish Nachricht. Ich habe jetzt mal in der alten MQTT 3.1 Spec nachgesehen, dort gibt es das DUP Bit noch (Scheinbar bei allen Nachrichten). Da haben wir nun den Grund für unser Problem mit dem MQTT Modul, es verwendet noch das MQTT 3.1 Protokoll.
p.s. sorry heute ich ich keine Zeit mehr, muß gleich weg

[Beta-User]

  kein Problem...

Falls jemand anderes testen will, anbei der Versuch, das 3.1.1-kompatibel zu machen, indem das DUP-Flag (hoffentlich) nur gesetzt wird, wenn es eine normale Publish-Message ist.

[hexenmeister]

Hallo allerseits,

nach dem Problemlösung habe ich seit zwei Tagen gesucht. Danke an Beta-User für den Link zu diesem Thread.
Ihr alle habt tolle Arbeit geleistet hier. Absolut Spitze!
Ich bin übrigens gestern sabend zu dem gleichen Ergebnis gekommen: der DUP Flag!
Darauf bin ich bei Lesen der Doku geklommen: http://docs.oasis-open.org/mqtt/mqtt/v3.1.1/os/mqtt-v3.1.1-os.html#_Toc398718033

If the DUP flag is set to 0, it indicates that this is the first occasion that the Client or Server has attempted to send this MQTT PUBLISH Packet. If the DUP flag is set to 1, it indicates that this might be re-delivery of an earlier attempt to send the Packet.
 
The DUP flag MUST be set to 1 by the Client or Server when it attempts to re-deliver a PUBLISH Packet [MQTT-3.3.1.-1]. The DUP flag MUST be set to 0 for all QoS 0 messages [MQTT-3.3.1-2].

The value of the DUP flag from an incoming PUBLISH packet is not propagated when the PUBLISH Packet is sent to subscribers by the Server. The DUP flag in the outgoing PUBLISH packet is set independently to the incoming PUBLISH packet, its value MUST be determined solely by whether the outgoing PUBLISH packet is a retransmission [MQTT-3.3.1-3].

Bin leider kein MQTT-Protokoll-Profi, jetzt müssen wir rausfinden, wann genau der Flag NICHT gesetzt werden muss. Also ob nur die QOS0 Messages betroffen sind oder alles, was nicht PUBLISH ist (ich meine aktuell wird auch nur für PUBLISH gesetzt, muss aber noch überprüfen => Quatsch, was ich da geschriben habe, in dem Puffer sind natürlich alle nicht bestätigte Nachrichten)

[hexenmeister]

Die Änderung von Beta-User ist die Lösung. Ich habe diese lediglich leicht ergänzt entsprechend dem, was in in DOku gefunden habe. Hoffe, ich habe das auch richtig interpretiert.

Code: [Auswählen]

   foreach my $message_id (keys %{$hash->{messages}}) {
          my $msg = $hash->{messages}->{$message_id}->{message};
          $msg->{dup} = $msg->{ispub} & $msg->{qos} == MQTT_QOS_AT_MOST_ONCE;
          DevIo_SimpleWrite($hash,$msg->bytes,undef);
   }

Ich teste noch ein wenig und checke dann ein.

[Beta-User]

Erst mal willkommen hier und Danke für das feedback.

Ich glaube, die Ergänzung ist an dieser Stelle an sich richtig so. ABER: die Logik in send_publish() kommt mir in der Hinsicht "kaputt" vor - da wird nämlich so eine Nachricht gar nicht mit einer Nummer versehen und dann auch nicht gequeued, so dass diese doppelte Bedingung gar nicht eintreffen kann? Oder bin ich auf dem Holzweg?

[Beta-User]

Nachbrenner-Frage: $msg->{qos} wird dann auch in den Queue-Hash übergeben, oder?

[hexenmeister]

Erst mal willkommen hier und Danke für das feedback.

Ich glaube, die Ergänzung ist an dieser Stelle an sich richtig so. ABER: die Logik in send_publish() kommt mir in der Hinsicht "kaputt" vor - da wird nämlich so eine Nachricht gar nicht mit einer Nummer versehen und dann auch nicht gequeued, so dass diese doppelte Bedingung gar nicht eintreffen kann? Oder bin ich auf dem Holzweg?

Da sagst Du was... Stimmt vollkommend, hier rächt sich, dass ich mich schon ewig nicht mit dem Modul beschäftigt habe (und die Ursprungsversion mit der Basis-Logik auch nicht von mir ist). Eigentlich dachte ich, das Modul ist reif zum Einmotten, jedoch sehe ich, dass es noch Nutzer gibt, denen es wichtig ist.

Die Abfrage nach QOS wäre hier tatsächlich Quatsch, da die Nachrichten mit QOS0 eh nicht bestätigt werden und der Pufferung entsprechend sinnlos ist.

[hexenmeister]

Nachbrenner-Frage: $msg->{qos} wird dann auch in den Queue-Hash übergeben, oder?

Meinst Du mit Queue "$hash->{messages}"? Ja, {qos} wird ja an die "send_xxx" subs mitgegeben und in Message.pm mit in die Nachricht (hash) mitgenommen. Nachricht-Hash landet dann in "$hash->{messages}->{msgiid}".

[Beta-User]

Meinst Du mit Queue "$hash->{messages}"? Ja, {qos} wird ja an die "send_xxx" subs mitgegeben und in Message.pm mit in die Nachricht (hash) mitgenommen. Nachricht-Hash landet dann in "$hash->{messages}->{msgiid}".

Das deckt sich nicht mit meinem Verständnis: Wenn, dann müßte es irgendein Unterhash von dem sein, was sich aus

Code: [Auswählen]

my $message = Net::MQTT::Message->new(%msg); ergibt. Vermutlich könnte man da auch auf die "inneren Werte" zugreifen, aber das hatte ich bei meinem Vorschlag übersehen...

Was sub send_publish() angeht - müßte das nicht so starten:

Code: [Auswählen]

sub send_publish($@) {
  my ($hash,%msg) = @_;
  if (!$msg{qos}) {


Eigentlich dachte ich, das Modul ist reif zum Einmotten, jedoch sehe ich, dass es noch Nutzer gibt, denen es wichtig ist.

Na ja, vielleicht sollte man es wirklich mittelfristig einmotten, aber wir bräuchten dann einen Plan, wie das gehen soll, damit niemand aus allen Wolken fällt. Da die meisten User vermutlich die kommenden Monate vor dem Problem stehen werden, dass sie updaten müssen, wäre vermutlich jetzt ein guter Zeitpunkt, um zumindest diese Kommunikation in die Richtung zu machen...
Stichworte:
- MQTT_BRIDGE direkt nach contrib, (v.a. auch UPDATE nicht vergessen)
- commandrefs von
-- MQTT_DEVICE Vorbemerkung in Richtung "use MQTT2_DEVICE instead" (für neue User!)
-- MQTT: (analog)
-- MQTT_GENERIC_BRIDGE (low prio): Beispiel (falls vorhanden weg von MQTT nach MQTT_CLIENT)
- Einen Satz Module (samt den 2016-er libs, falls getestet ist, dass die "ok" sind) mal aktuell ausliefern, damit "updater" ohne cpan auskommen, in ca. 6 Monaten die libs löschen, Installation dann nur noch via cpan?
- in ca. 12-18 Monaten dann "BRIDGE" nach "deprecated", MQTT+MQTT_DEVICE nach contrib (oder in dem Zug der Entfernung der libs alles "mittelfristige" direkt nach contrib?

@Rudi:
Gibt es eigentlich einen Plan für 6.1? (Spätestens,) wenn "MQTT-classic" raus ist, wäre es eventuell Zeit für einen Versionswechsel (kann auch 6.2 sein)? (Aber bitte nicht grade jetzt, solange das mit CUL_HM noch nicht wieder rund ist).