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
Ich habe versucht die Logmeldung in diesem Fall zu vermeiden, habe es aber nicht getestet mangels passende Geraete.
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
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.
ZitatWas 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.
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