Autor Thema: [erledigt] esp8622 mit DeepSleep an MQTT2: keepalive check schlägt fehl  (Gelesen 685 mal)

Offline Kristof

  • New Member
  • *
  • Beiträge: 31
Hallo Forum,

ich habe auf einem Wemos D1 Mini ein Script laufen, dass regelmäßig Sensordaten an den MQTT2-Server auf dem FHEM-Server (raspi) schickt und dann, um die Batterie zu schonen, in einen Tiefschlaf geht. Das klappt soweit auch prima, die Daten kommen an und ich kann die Readings verarbeiten. Das MQTT2 Device wurde auch automatisch angelegt. Mein Problem ist, dass mein Log jetzt vollläuft mit den "keepalive check"-Meldungen.
Das verstehe ich nicht, denn es wird offenbar eine korrekte keepalive-Zeit übertragen. Ich wecke den D1 Mini aktuell alle 15 Minuten auf und habe im Script die keepalive-Zeit auf 18 Minuten eingestellt. Das kommt auch so am Server an:
Hier mal exemplarisch ein Auszug aus dem Log dazu:
2020.11.14 13:29:43 4: Connection accepted from myMQTTServer_192.168.1.48_54327
2020.11.14 13:29:43 5: in:  CONNECT: (16)6(0)(4)MQTT(4)&(4)8(0)(14)D1MiniZisterne(0)(17)draussen/Zisterne(0)(7)offline
2020.11.14 13:29:43 4:   myMQTTServer_192.168.1.48_54327 cid:D1MiniZisterne CONNECT V:4 keepAlive:1080 LWT:draussen/Zisterne:offline
2020.11.14 13:29:43 5: out: CONNACK:  (2)(0)(0)
2020.11.14 13:29:43 5: in:  PUBLISH: 0(25)(0)(17)draussen/Zisterneonline
2020.11.14 13:29:43 4:   myMQTTServer_192.168.1.48_54327 D1MiniZisterne PUBLISH draussen/Zisterne:online
2020.11.14 13:29:43 5: myMQTTServer: dispatch autocreate=simple\000D1MiniZisterne\000draussen/Zisterne\000online
2020.11.14 13:29:43 5: in:  SUBSCRIBE: (130)(12)(0)(2)(0)(7)inTopic(0)
2020.11.14 13:29:43 4:   myMQTTServer_192.168.1.48_54327 D1MiniZisterne SUBSCRIBE
2020.11.14 13:29:43 4:   topic:inTopic qos:0
2020.11.14 13:29:43 5: out: SUBACK: (144)(3)(0)(2)(1)
2020.11.14 13:29:43 5: in:  PUBLISH: 1(28)(0)(22)draussen/Zisterne/RSSI -77
2020.11.14 13:29:43 4:   myMQTTServer_192.168.1.48_54327 D1MiniZisterne PUBLISH draussen/Zisterne/RSSI: -77
2020.11.14 13:29:43 5: myMQTTServer: dispatch autocreate=simple\000D1MiniZisterne\000draussen/Zisterne/RSSI\000 -77
2020.11.14 13:29:43 5: in:  PUBLISH: 1!(0)(26)draussen/Zisterne/Spannung 4.93
2020.11.14 13:29:43 4:   myMQTTServer_192.168.1.48_54327 D1MiniZisterne PUBLISH draussen/Zisterne/Spannung: 4.93
2020.11.14 13:29:43 5: myMQTTServer: dispatch autocreate=simple\000D1MiniZisterne\000draussen/Zisterne/Spannung\000 4.93
2020.11.14 13:29:43 5: in:  PUBLISH: 1#(0)(28)draussen/Zisterne/Fuellstand 7.83
2020.11.14 13:29:43 4:   myMQTTServer_192.168.1.48_54327 D1MiniZisterne PUBLISH draussen/Zisterne/Fuellstand: 7.83
2020.11.14 13:29:43 5: myMQTTServer: dispatch autocreate=simple\000D1MiniZisterne\000draussen/Zisterne/Fuellstand\000 7.83

Eine Weile später kommt die nächste Nachricht vom D1 Mini:
2020.11.14 13:41:22 4: Connection accepted from myMQTTServer_192.168.1.48_51846
Trotzdem kommt etwas später das hier:
2020.11.14 13:56:47 3: myMQTTServer: myMQTTServer_192.168.1.48_54327/D1MiniZisterne left us (keepalive check)
2020.11.14 13:56:47 4: Closing second connection for D1MiniZisterne/192.168.1.48 without lwt

Hängt das vielleicht damit zusammen, dass ja mein D1 jedes Mal eine neuen WLAN-Verbindung aufbaut und daher jedes Mal einen anderen Port bekommt (war ja erst 54327, dann 51846)? Wenn ja, was kann ich dann tun? Kann ich das "keepalive" nicht irgendwie an das Device (hier "D1MiniZisterne") hängen, statt an IP_Port? Oder liege ich ganz falsch und das muss die Problemursache wo ganz anders suchen?
Bin für jeden Hinweis dankbar!

Hier noch das Listing vom MQTT2_Server:
Internals:
   CONNECTS   11
   DEF        1883 global
   FD         37
   FUUID      5fafc4cb-f33f-1bb4-26cb-e529e165ba494d98
   NAME       myMQTTServer
   NR         235
   PORT       1883
   STATE      Initialized
   TYPE       MQTT2_SERVER
   READINGS:
     2020-11-14 15:42:57   RETAIN          {"draussen/Zisterne/Fuellstand":" 7.55","draussen/Zisterne/RSSI":" -73","draussen/Zisterne/Spannung":" 4.95"}
     2020-11-14 15:42:57   nrclients       7
     2020-11-14 12:57:57   state           Initialized
   clients:
     myMQTTServer_192.168.1.48_49350 1
     myMQTTServer_192.168.1.48_51247 1
     myMQTTServer_192.168.1.48_51737 1
     myMQTTServer_192.168.1.48_53869 1
     myMQTTServer_192.168.1.48_58023 1
     myMQTTServer_192.168.1.48_60192 1
     myMQTTServer_192.168.1.48_65495 1
   retain:
     draussen/Zisterne/Fuellstand:
       ts         1605364977.80987
       val         7.55
     draussen/Zisterne/RSSI:
       ts         1605364977.5059
       val         -73
     draussen/Zisterne/Spannung:
       ts         1605364977.52311
       val         4.95
Attributes:
   room       System
   verbose    5

und vom Device:
Internals:
   CFGFN     
   CID        D1MiniZisterne
   DEF        D1MiniZisterne
   DEVICETOPIC MQTT2_D1MiniZisterne
   FUUID      5fafc702-f33f-1bb4-4dc3-d099dda5c9d77728
   IODev      myMQTTServer
   LASTInputDev myMQTTServer
   MSGCNT     40
   NAME       MQTT2_D1MiniZisterne
   NR         247
   STATE      ???
   TYPE       MQTT2_DEVICE
   myMQTTServer_MSGCNT 40
   myMQTTServer_TIME 2020-11-14 15:42:57
   READINGS:
     2020-11-14 15:42:57   Fuellstand       7.55
     2020-11-14 15:42:57   RSSI             -73
     2020-11-14 15:42:57   Spannung         4.95
     2020-11-14 15:42:57   Zisterne        online
Attributes:
   IODev      myMQTTServer
   readingList D1MiniZisterne:draussen/Zisterne:.* Zisterne
D1MiniZisterne:draussen/Zisterne/RSSI:.* RSSI
D1MiniZisterne:draussen/Zisterne/Spannung:.* Spannung
D1MiniZisterne:draussen/Zisterne/Fuellstand:.* Fuellstand
   room       Zimmer->Draussen

Gruß
Kristof
« Letzte Änderung: 16 November 2020, 21:17:30 von Kristof »

Offline rudolfkoenig

  • Administrator
  • Hero Member
  • *****
  • Beiträge: 24905
Antw:esp8622 mit DeepSleep an MQTT2: keepalive check schlägt fehl
« Antwort #1 am: 15 November 2020, 12:27:32 »
Ich habe versucht die Logmeldung in diesem Fall zu vermeiden, habe es aber nicht getestet mangels passende Geraete.

Offline Kristof

  • New Member
  • *
  • Beiträge: 31
Antw:esp8622 mit DeepSleep an MQTT2: keepalive check schlägt fehl
« Antwort #2 am: 16 November 2020, 09:37:34 »
Habe heute um 8:24 ein Update durchgeführt und dann FHEM neu gestartet.
Die "... left us"-Meldungen kommen leider immer noch.

Hier das Logfile:
2020.11.16 09:00:53 4: Connection accepted from myMQTTServer_192.168.1.48_60822
2020.11.16 09:00:53 5: in:  CONNECT: (16)6(0)(4)MQTT(4)&(4)8(0)(14)D1MiniZisterne(0)(17)draussen/Zisterne(0)(7)offline
2020.11.16 09:00:53 4:   myMQTTServer_192.168.1.48_60822 cid:D1MiniZisterne CONNECT V:4 keepAlive:1080 LWT:draussen/Zisterne:offline
2020.11.16 09:00:53 5: out: CONNACK:  (2)(0)(0)
2020.11.16 09:00:53 5: in:  PUBLISH: 0(25)(0)(17)draussen/Zisterneonline
2020.11.16 09:00:53 4:   myMQTTServer_192.168.1.48_60822 D1MiniZisterne PUBLISH draussen/Zisterne:online
2020.11.16 09:00:53 5: myMQTTServer: dispatch autocreate=simple\000D1MiniZisterne\000draussen/Zisterne\000online
2020.11.16 09:00:54 4: MQTT2_DEVICE_Parse: MQTT2_D1MiniZisterne draussen/Zisterne => Zisterne
2020.11.16 09:00:54 5: in:  SUBSCRIBE: (130)(12)(0)(2)(0)(7)inTopic(0)
2020.11.16 09:00:54 4:   myMQTTServer_192.168.1.48_60822 D1MiniZisterne SUBSCRIBE
2020.11.16 09:00:54 4:   topic:inTopic qos:0
2020.11.16 09:00:54 5: out: SUBACK: (144)(3)(0)(2)(1)
2020.11.16 09:00:54 5: in:  PUBLISH: 1(28)(0)(22)draussen/Zisterne/RSSI -75
2020.11.16 09:00:54 4:   myMQTTServer_192.168.1.48_60822 D1MiniZisterne PUBLISH draussen/Zisterne/RSSI: -75
2020.11.16 09:00:54 5: myMQTTServer: dispatch autocreate=simple\000D1MiniZisterne\000draussen/Zisterne/RSSI\000 -75
2020.11.16 09:00:54 4: MQTT2_DEVICE_Parse: MQTT2_D1MiniZisterne draussen/Zisterne/RSSI => RSSI
2020.11.16 09:00:54 5: in:  PUBLISH: 1!(0)(26)draussen/Zisterne/Spannung 4.70
2020.11.16 09:00:54 4:   myMQTTServer_192.168.1.48_60822 D1MiniZisterne PUBLISH draussen/Zisterne/Spannung: 4.70
2020.11.16 09:00:54 5: myMQTTServer: dispatch autocreate=simple\000D1MiniZisterne\000draussen/Zisterne/Spannung\000 4.70
2020.11.16 09:00:54 4: MQTT2_DEVICE_Parse: MQTT2_D1MiniZisterne draussen/Zisterne/Spannung => Spannung
2020.11.16 09:00:54 5: in:  PUBLISH: 1#(0)(28)draussen/Zisterne/Fuellstand 7.12
2020.11.16 09:00:54 4:   myMQTTServer_192.168.1.48_60822 D1MiniZisterne PUBLISH draussen/Zisterne/Fuellstand: 7.12
2020.11.16 09:00:54 5: myMQTTServer: dispatch autocreate=simple\000D1MiniZisterne\000draussen/Zisterne/Fuellstand\000 7.12
2020.11.16 09:00:54 4: MQTT2_DEVICE_Parse: MQTT2_D1MiniZisterne draussen/Zisterne/Fuellstand => Fuellstand
2020.11.16 09:12:09 2: AttrTemplates: got 215 entries
2020.11.16 09:15:11 4: Connection accepted from myMQTTServer_192.168.1.48_56291
2020.11.16 09:15:11 5: in:  CONNECT: (16)6(0)(4)MQTT(4)&(4)8(0)(14)D1MiniZisterne(0)(17)draussen/Zisterne(0)(7)offline
2020.11.16 09:15:11 4:   myMQTTServer_192.168.1.48_56291 cid:D1MiniZisterne CONNECT V:4 keepAlive:1080 LWT:draussen/Zisterne:offline
2020.11.16 09:15:11 5: out: CONNACK:  (2)(0)(0)
2020.11.16 09:15:11 5: in:  PUBLISH: 0(25)(0)(17)draussen/Zisterneonline
2020.11.16 09:15:11 4:   myMQTTServer_192.168.1.48_56291 D1MiniZisterne PUBLISH draussen/Zisterne:online
2020.11.16 09:15:11 5: myMQTTServer: dispatch autocreate=simple\000D1MiniZisterne\000draussen/Zisterne\000online
2020.11.16 09:15:11 4: MQTT2_DEVICE_Parse: MQTT2_D1MiniZisterne draussen/Zisterne => Zisterne
2020.11.16 09:15:11 5: in:  SUBSCRIBE: (130)(12)(0)(2)(0)(7)inTopic(0)
2020.11.16 09:15:11 4:   myMQTTServer_192.168.1.48_56291 D1MiniZisterne SUBSCRIBE
2020.11.16 09:15:11 4:   topic:inTopic qos:0
2020.11.16 09:15:11 5: out: SUBACK: (144)(3)(0)(2)(1)
2020.11.16 09:15:11 5: in:  PUBLISH: 1(28)(0)(22)draussen/Zisterne/RSSI -73
2020.11.16 09:15:11 4:   myMQTTServer_192.168.1.48_56291 D1MiniZisterne PUBLISH draussen/Zisterne/RSSI: -73
2020.11.16 09:15:11 5: myMQTTServer: dispatch autocreate=simple\000D1MiniZisterne\000draussen/Zisterne/RSSI\000 -73
2020.11.16 09:15:11 4: MQTT2_DEVICE_Parse: MQTT2_D1MiniZisterne draussen/Zisterne/RSSI => RSSI
2020.11.16 09:15:11 5: in:  PUBLISH: 1!(0)(26)draussen/Zisterne/Spannung 4.70
2020.11.16 09:15:11 4:   myMQTTServer_192.168.1.48_56291 D1MiniZisterne PUBLISH draussen/Zisterne/Spannung: 4.70
2020.11.16 09:15:11 5: myMQTTServer: dispatch autocreate=simple\000D1MiniZisterne\000draussen/Zisterne/Spannung\000 4.70
2020.11.16 09:15:11 4: MQTT2_DEVICE_Parse: MQTT2_D1MiniZisterne draussen/Zisterne/Spannung => Spannung
2020.11.16 09:15:11 5: in:  PUBLISH: 1#(0)(28)draussen/Zisterne/Fuellstand 7.14
2020.11.16 09:15:11 4:   myMQTTServer_192.168.1.48_56291 D1MiniZisterne PUBLISH draussen/Zisterne/Fuellstand: 7.14
2020.11.16 09:15:11 5: myMQTTServer: dispatch autocreate=simple\000D1MiniZisterne\000draussen/Zisterne/Fuellstand\000 7.14
2020.11.16 09:15:11 4: MQTT2_DEVICE_Parse: MQTT2_D1MiniZisterne draussen/Zisterne/Fuellstand => Fuellstand
2020.11.16 09:28:03 4: Closing second connection for D1MiniZisterne/192.168.1.48 without lwt
2020.11.16 09:28:03 3: myMQTTServer: myMQTTServer_192.168.1.48_60822/D1MiniZisterne left us (keepalive check)

sowie die Listings vom Server:
Internals:
   CONNECTS   3
   DEF        1883 global
   FD         37
   FUUID      5fafc4cb-f33f-1bb4-26cb-e529e165ba494d98
   NAME       myMQTTServer
   NR         235
   PORT       1883
   STATE      Initialized
   TYPE       MQTT2_SERVER
   READINGS:
     2020-11-16 09:29:28   RETAIN          {"draussen/Zisterne":"offline","draussen/Zisterne/Fuellstand":" 7.10","draussen/Zisterne/RSSI":" -71","draussen/Zisterne/Spannung":" 4.70"}
     2020-11-16 09:29:27   nrclients       2
     2020-11-16 08:51:34   state           Initialized
   clients:
     myMQTTServer_192.168.1.48_56291 1
     myMQTTServer_192.168.1.48_57937 1
   retain:
     draussen/Zisterne:
       ts         1605513095.14209
       val        offline
     draussen/Zisterne/Fuellstand:
       ts         1605515368.0828
       val         7.10
     draussen/Zisterne/RSSI:
       ts         1605515367.77873
       val         -71
     draussen/Zisterne/Spannung:
       ts         1605515367.79536
       val         4.70
Attributes:
   room       System
   verbose    5

und Device:
Internals:
   CID        D1MiniZisterne
   DEF        D1MiniZisterne
   DEVICETOPIC MQTT2_D1MiniZisterne
   FUUID      5fafc702-f33f-1bb4-4dc3-d099dda5c9d77728
   IODev      myMQTTServer
   LASTInputDev myMQTTServer
   MSGCNT     12
   NAME       MQTT2_D1MiniZisterne
   NR         236
   STATE      ???
   TYPE       MQTT2_DEVICE
   myMQTTServer_MSGCNT 12
   myMQTTServer_TIME 2020-11-16 09:29:28
   READINGS:
     2020-11-16 09:29:28   Fuellstand       7.10
     2020-11-16 09:29:27   RSSI             -71
     2020-11-16 09:29:27   Spannung         4.70
     2020-11-16 09:29:27   Zisterne        online
Attributes:
   IODev      myMQTTServer
   readingList D1MiniZisterne:draussen/Zisterne:.* Zisterne
D1MiniZisterne:draussen/Zisterne/RSSI:.* RSSI
D1MiniZisterne:draussen/Zisterne/Spannung:.* Spannung
D1MiniZisterne:draussen/Zisterne/Fuellstand:.* Fuellstand
   room       Zimmer->Draussen
   verbose    5

Was mir aufgefallen ist, ist dass der Server von 2 Clients ausgeht, obwohl sie ja die selbe IP und die selbe CID haben.

Gruß
Kristof

Offline rudolfkoenig

  • Administrator
  • Hero Member
  • *****
  • Beiträge: 24905
Antw:esp8622 mit DeepSleep an MQTT2: keepalive check schlägt fehl
« Antwort #3 am: 16 November 2020, 10:11:13 »
Mein Fehler, ich habe den falschen Hash abgefragt.

Entweder in der Zeile 95 $hash gegen $cHash selbst tauschen
--- FHEM/00_MQTT2_SERVER.pm (revision 23161)
+++ FHEM/00_MQTT2_SERVER.pm (working copy)
@@ -92,7 +92,7 @@
       $msgName .= "/".$cHash->{cid} if($cHash->{cid});
       CommandDelete(undef, $clName);
       Log3 $hash, 3, "$hash->{NAME}: $msgName left us (keepalive check)"
-        if(!$hash->{isReplaced});
+        if(!$cHash->{isReplaced});
     }
   }
   InternalTimer($now+10, "MQTT2_SERVER_keepaliveChecker", $hash, 0);
oder morgen ab 8 ein FHEM update machen.

Zitat
Was mir aufgefallen ist, ist dass der Server von 2 Clients ausgeht, obwohl sie ja die selbe IP und die selbe CID haben.
Es sind ja auch zwei Verbindungen mit der gleichen CID vom gleichen IP vorhanden, die alte Verbindung wurde ja frecherweise nie geschlossen.
Das versucht der MQTT2_SERVER zu ignorieren, sozusagen bei unflaetigen Kindern nachsichtig zu sein.

Offline Kristof

  • New Member
  • *
  • Beiträge: 31
Antw:esp8622 mit DeepSleep an MQTT2: keepalive check schlägt fehl
« Antwort #4 am: 16 November 2020, 21:16:46 »
Jetzt tut's einwandfrei!  ;D
Keine "... left us"-Meldungen mehr im Log. Habe dann um 20:23 den Akku abgezogen von meinem D1 und siehe da, um 20:50 (18 Minuten * keepalivefactor von 1,5 = 27 Minuten) wurde der "letzte Wille" übertragen und es kam auch die Meldung im Log. Ich würde sagen: Thema erfolgreich erledigt.

Tausend Dank Rudi!

Gruß
Kristof