MQTT2_SERVER verwaist

BeetleX · 28 Januar 2019, 21:50:28

Hallo,

ich hatte seit einigen Wochen bis heute morgen 3 sonoffs/tasmota mit dem MQTT2_SERVER am laufen.
Plötzlich sind alle Verbindungen tot, die sonoffs sagen "21:42:46 MQT: Verbindungsversuch...
21:42:51 MQT: Verbindung fehlgeschlagen aufgrund von cubie2:1883, rc -2. Wiederversuch in 10 s".
Trotz "verbose 5" kann ich auch nichts im log finden.
Im Retain stehen noch alte topics, auch die aktuellen.

Hier das Listing des Servers.

Code Auswählen


Internals:
   DEF        1883 global
   FD         67
   FUUID      5c4f58ad-f33f-e163-aced-1de0b8c7b21001ea
   NAME       myMqttServer
   NR         977
   PORT       1883
   STATE      Initialized
   TYPE       MQTT2_SERVER
   READINGS:
     2019-01-28 08:43:02   RETAIN          {"tele/sonoff/LWT":"Offline","tele/sonoff_1089/LWT":"Offline","tele/sonoff_2705/LWT":"Offline","tele/sonoff_C1EB89/LWT":"Offline","tele/sonoff_bad/LWT":"Offline","tele/sonoff_bad_2953/LWT":"Offline","tele/sonoff_garten/LWT":"Offline","tele/sonoff_kueche/LWT":"Offline"}
     2019-01-28 20:31:57   nrclients       0
     2019-01-28 20:31:57   state           Initialized
   clients:
   retain:
     tele/sonoff/LWT:
       ts         1548703918.30297
       val        Offline
     tele/sonoff_1089/LWT:
       ts         1548703918.30297
       val        Offline
     tele/sonoff_2705/LWT:
       ts         1548703918.30297
       val        Offline
     tele/sonoff_C1EB89/LWT:
       ts         1548703918.30297
       val        Offline
     tele/sonoff_bad/LWT:
       ts         1548703918.30297
       val        Offline
     tele/sonoff_bad_2953/LWT:
       ts         1548703918.30297
       val        Offline
     tele/sonoff_garten/LWT:
       ts         1548703918.30297
       val        Offline
     tele/sonoff_kueche/LWT:
       ts         1548703918.30297
       val        Offline
Attributes:
   autocreate 1
   room       MQTT
   verbose    5

Habe verzweifelt Restarts und Update durch. Was kann ich zum Debugging noch tun?

VG Holger

rudolfkoenig · 28 Januar 2019, 22:32:40

- Kannst du dich von einem anderen(!) Rechner per "mosquitto_sub -h cubie2 -t #" verbinden?
- Siehst du auf dem cubie2 als root mit "tcpdump port 1883" Pakete?
- Was meldet als root auf dem cubie2 "lsof -n | grep 1883"?
- Steht nach einem "modify myMqttServer 1883 global" etwas im FHEM-Log? (attr myMqttServer verbose 5 bitte lassen).

BeetleX · 30 Januar 2019, 20:04:09

Nach einigen Sessions läuft es wieder, aber...
hier meine Ergebnisse für den Tot-Zustand:

- Den Mosquitto-Test muss ich später nachholen...
- tcpdump fängt nichts
- lsof bringt nur "perl 27959 fhem 67u IPv4 157046 0t0 TCP *:1883 (LISTEN)"
- nach modify steht im log nur "myMqttServer: port 1883 opened"

Etwas Spielerei an der Fritz brachte plötzlich eine Verbindung ("autom. Portfreigabe erlaubt") - aber nur kurzzeitig -!?
Da es an der 7490 einen Tag vorher ein Labor-Update gab, habe ich erstmal auf 7.01 zurückgestellt.
Weiterhin den Repeater entfernt.
Alles was Spannung braucht neu gestartet.
nrofclients weiterhin 0.

Dann in einer sonoff als host statt "cubie2" die IP eingetragen: Erfolg!
Bei der nächsten dito, aber: kein Erfolg!?
Nochmal hin und hergestellt: Erfolg, auch bei der dritten.

Was ist nun das Ergebnis? Da ja vorher alles über 3 Wochen problemlos lief, bin ich etwas ratlos...

Nun zum FileLog:

Code Auswählen


2019-01-30_15:43:50 myMqttServer nrclients: 3
2019-01-30_15:58:19 myMqttServer nrclients: 2
2019-01-30_15:58:20 myMqttServer nrclients: 3
2019-01-30_16:07:43 myMqttServer nrclients: 2
2019-01-30_16:07:43 myMqttServer nrclients: 3
2019-01-30_16:21:53 myMqttServer nrclients: 2
2019-01-30_16:22:03 myMqttServer nrclients: 3
2019-01-30_16:26:53 myMqttServer nrclients: 4

Es schwankt,
nach 2 kommt sofort wieder 3
und hin und wieder mal eine 4 (es gibt definitiv nur 3 Geräte)

Kann ich zur Aufklärung noch etwas beitragen?

VG Holger

rudolfkoenig · 30 Januar 2019, 20:23:30

An deinem urspruenglichen Problem war der Router (Fritzbox) schuld: FHEM hat zwar den Serverport angeboten, es kamen aber keine Anfragen an. Vermutlich muss man mit der Laborversion einen weiteren Schalter aktivieren, damit die Geraete untereinander kommunizieren koennen.

Das neue Problem (sofern es eins ist) sollte man mit "attr myMqttServer verbose 5" und einem Blick ins FHEM-Log klaeren koennen.

BeetleX · 30 Januar 2019, 22:02:06

Es gibt zwar diesen Schalter fürs WLAN (WLAN untereinander) und fürs (hier nicht relevente) Gastnetz, aber das Verhalten war ja nicht so richtig determiniert.

etwas Log habe ich hier:

Code Auswählen


2019.01.30 02:01:45 5: PINGREQ: 
2019.01.30 02:01:45 4: myMqttServer_172.16.1.205_49163 DVES_C1EB89 PINGREQ
2019.01.30 02:01:48 5: PINGREQ: 
2019.01.30 02:01:48 4: myMqttServer_172.16.1.204_49157 DVES_E9C441 PINGREQ
2019.01.30 02:01:50 5: PINGREQ: 
2019.01.30 02:01:50 4: myMqttServer_172.16.1.203_49159 DVES_8C2A91 PINGREQ
2019.01.30 02:01:55 5: PINGREQ: 
2019.01.30 02:01:55 4: myMqttServer_172.16.1.205_49163 DVES_C1EB89 PINGREQ
2019.01.30 02:01:58 5: PINGREQ: 
2019.01.30 02:01:58 4: myMqttServer_172.16.1.204_49157 DVES_E9C441 PINGREQ
2019.01.30 02:02:00 5: PINGREQ: 
2019.01.30 02:02:00 4: myMqttServer_172.16.1.203_49159 DVES_8C2A91 PINGREQ
2019.01.30 02:02:00 5: PUBLISH: (0)(22)tele/sonoff_bad/UPTIME{"Time":"2019-01-30T02:02:00","Uptime":"0T04:08:48"}
2019.01.30 02:02:00 4: myMqttServer_172.16.1.205_49163 DVES_C1EB89 PUBLISH tele/sonoff_bad/UPTIME:{"Time":"2019-01-30T02:02:00","Uptime":"0T04:08:48"}
2019.01.30 02:02:00 5: myMqttServer: dispatch autocreate:DVES_C1EB89:tele/sonoff_bad/UPTIME:{"Time":"2019-01-30T02:02:00","Uptime":"0T04:08:48"}
2019.01.30 02:02:00 5: PUBLISH: (0)(25)tele/sonoff_garten/UPTIME{"Time":"2019-01-30T02:02:00","Uptime":"0T05:15:08"}
2019.01.30 02:02:00 4: myMqttServer_172.16.1.204_49157 DVES_E9C441 PUBLISH tele/sonoff_garten/UPTIME:{"Time":"2019-01-30T02:02:00","Uptime":"0T05:15:08"}
2019.01.30 02:02:00 5: myMqttServer: dispatch autocreate:DVES_E9C441:tele/sonoff_garten/UPTIME:{"Time":"2019-01-30T02:02:00","Uptime":"0T05:15:08"}
2019.01.30 02:02:01 5: PUBLISH: (0)(25)tele/sonoff_kueche/UPTIME{"Time":"2019-01-30T02:02:00","Uptime":"0T04:22:28"}
2019.01.30 02:02:01 4: myMqttServer_172.16.1.203_49159 DVES_8C2A91 PUBLISH tele/sonoff_kueche/UPTIME:{"Time":"2019-01-30T02:02:00","Uptime":"0T04:22:28"}
2019.01.30 02:02:01 5: myMqttServer: dispatch autocreate:DVES_8C2A91:tele/sonoff_kueche/UPTIME:{"Time":"2019-01-30T02:02:00","Uptime":"0T04:22:28"}
2019.01.30 02:02:05 5: PINGREQ: 
2019.01.30 02:02:05 4: myMqttServer_172.16.1.205_49163 DVES_C1EB89 PINGREQ
2019.01.30 02:02:08 5: PINGREQ: 
2019.01.30 02:02:08 4: myMqttServer_172.16.1.204_49157 DVES_E9C441 PINGREQ
2019.01.30 02:02:10 5: PINGREQ: 
2019.01.30 02:02:10 4: myMqttServer_172.16.1.203_49159 DVES_8C2A91 PINGREQ
2019.01.30 02:02:14 5: PUBLISH: (0)(24)tele/sonoff_garten/STATE{"Time":"2019-01-30T02:02:14","Uptime":"0T05:15:22","Vcc":3.454,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER":"OFF","Wifi":{"AP":1,"SSId":".............","BSSId":".................","Channel":1,"RSSI":42}}
2019.01.30 02:02:14 4: myMqttServer_172.16.1.204_49157 DVES_E9C441 PUBLISH tele/sonoff_garten/STATE:{"Time":"2019-01-30T02:02:14","Uptime":"0T05:15:22","Vcc":3.454,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER":"OFF","Wifi":{"AP":1,"SSId":".............","BSSId":".................","Channel":1,"RSSI":42}}
2019.01.30 02:02:14 5: myMqttServer: dispatch autocreate:DVES_E9C441:tele/sonoff_garten/STATE:{"Time":"2019-01-30T02:02:14","Uptime":"0T05:15:22","Vcc":3.454,"SleepMode":"Dynamic","Sleep":50,"LoadAvg":19,"POWER":"OFF","Wifi":{"AP":1,"SSId":".............","BSSId":".................","Channel":1,"RSSI":42}}
2019.01.30 02:02:14 5: PUBLISH: (0)(25)tele/sonoff_garten/SENSOR{"Time":"2019-01-30T02:02:14","ENERGY":{"TotalStartTime":"2018-12-20T07:20:03","Total":9.613,"Yesterday":0.048,"Today":0.000,"Period":0,"Power":0,"ApparentPower":0,"ReactivePower":0,"Factor":0.00,"Voltage":0,"Current":0.000}}
2019.01.30 02:02:14 4: myMqttServer_172.16.1.204_49157 DVES_E9C441 PUBLISH tele/sonoff_garten/SENSOR:{"Time":"2019-01-30T02:02:14","ENERGY":{"TotalStartTime":"2018-12-20T07:20:03","Total":9.613,"Yesterday":0.048,"Today":0.000,"Period":0,"Power":0,"ApparentPower":0,"ReactivePower":0,"Factor":0.00,"Voltage":0,"Current":0.000}}
2019.01.30 02:02:14 5: myMqttServer: dispatch autocreate:DVES_E9C441:tele/sonoff_garten/SENSOR:{"Time":"2019-01-30T02:02:14","ENERGY":{"TotalStartTime":"2018-12-20T07:20:03","Total":9.613,"Yesterday":0.048,"Today":0.000,"Period":0,"Power":0,"ApparentPower":0,"ReactivePower":0,"Factor":0.00,"Voltage":0,"Current":0.000}}
2019.01.30 02:02:15 5: PINGREQ: 
2019.01.30 02:02:15 4: myMqttServer_172.16.1.205_49163 DVES_C1EB89 PINGREQ
2019.01.30 02:02:18 5: PINGREQ: 
2019.01.30 02:02:18 4: myMqttServer_172.16.1.204_49157 DVES_E9C441 PINGREQ
2019.01.30 02:02:20 5: PINGREQ: 
2019.01.30 02:02:20 4: myMqttServer_172.16.1.203_49159 DVES_8C2A91 PINGREQ
2019.01.30 02:02:25 5: PINGREQ: 
2019.01.30 02:02:25 4: myMqttServer_172.16.1.205_49163 DVES_C1EB89 PINGREQ
2019.01.30 02:02:28 5: PINGREQ: 
2019.01.30 02:02:28 4: myMqttServer_172.16.1.204_49157 DVES_E9C441 PINGREQ
2019.01.30 02:02:30 5: PINGREQ: 
2019.01.30 02:02:30 4: myMqttServer_172.16.1.203_49159 DVES_8C2A91 PINGREQ
2019.01.30 02:02:35 5: PINGREQ: 
2019.01.30 02:02:35 4: myMqttServer_172.16.1.205_49163 DVES_C1EB89 PINGREQ
2019.01.30 02:02:38 5: PINGREQ: 
2019.01.30 02:02:38 4: myMqttServer_172.16.1.204_49157 DVES_E9C441 PINGREQ
2019.01.30 02:02:40 5: PINGREQ: 
2019.01.30 02:02:40 4: myMqttServer_172.16.1.203_49159 DVES_8C2A91 PINGREQ
2019.01.30 02:02:45 5: PINGREQ: 
2019.01.30 02:02:45 4: myMqttServer_172.16.1.205_49163 DVES_C1EB89 PINGREQ
2019.01.30 02:02:48 5: PINGREQ: 
2019.01.30 02:02:48 4: myMqttServer_172.16.1.204_49157 DVES_E9C441 PINGREQ
2019.01.30 02:02:50 5: PINGREQ: 
2019.01.30 02:02:50 4: myMqttServer_172.16.1.203_49159 DVES_8C2A91 PINGREQ
2019.01.30 02:02:52 2: hub: disconnect
2019.01.30 02:02:55 5: PINGREQ: 
2019.01.30 02:02:55 4: myMqttServer_172.16.1.205_49163 DVES_C1EB89 PINGREQ
2019.01.30 02:02:58 5: PINGREQ: 
2019.01.30 02:02:58 4: myMqttServer_172.16.1.204_49157 DVES_E9C441 PINGREQ
2019.01.30 02:03:00 5: PINGREQ: 
2019.01.30 02:03:00 4: myMqttServer_172.16.1.203_49159 DVES_8C2A91 PINGREQ
2019.01.30 02:03:04 3: hub: connected
2019.01.30 02:03:06 5: PINGREQ: 
2019.01.30 02:03:06 4: myMqttServer_172.16.1.205_49163 DVES_C1EB89 PINGREQ
2019.01.30 02:03:08 5: PINGREQ: 
2019.01.30 02:03:08 4: myMqttServer_172.16.1.204_49157 DVES_E9C441 PINGREQ
2019.01.30 02:03:08 3: hub: new config 
2019.01.30 02:03:10 5: PINGREQ: 
2019.01.30 02:03:10 4: myMqttServer_172.16.1.203_49159 DVES_8C2A91 PINGREQ
2019.01.30 02:03:16 5: PINGREQ: 
2019.01.30 02:03:16 4: myMqttServer_172.16.1.205_49163 DVES_C1EB89 PINGREQ
2019.01.30 02:03:18 5: PINGREQ: 
2019.01.30 02:03:18 4: myMqttServer_172.16.1.204_49157 DVES_E9C441 PINGREQ
2019.01.30 02:03:20 5: PINGREQ: 
2019.01.30 02:03:20 4: myMqttServer_172.16.1.203_49159 DVES_8C2A91 PINGREQ

rudolfkoenig · 30 Januar 2019, 22:41:33

Um die wechselnden nrclients zu begruenden braucht man den Log auch fuer diesen Zeitraum.
Dabei muessen CONNECT Meldugen im Log auftauchen

BeetleX · 31 Januar 2019, 07:17:30

Hier ein snip und die betreffende Zeit komplett im zip:

Code Auswählen


2019.01.30 16:26:53 4: Connection accepted from myMqttServer_172.16.1.205_49209
2019.01.30 16:26:53 5: CONNECT: (0)(4)MQTT(4)(238)(0)(10)(0)(11)DVES_C1EB89(0)(19)tele/sonoff_bad/LWT(0)(7)Offline(0)(9)DVES_USER(0)(8)xxx
2019.01.30 16:26:53 4: myMqttServer_172.16.1.205_49209 DVES_C1EB89 CONNECT V:4 keepAlive:10 LWT:tele/sonoff_bad/LWT:Offline usr:DVES_USER
2019.01.30 16:26:53 5: PUBLISH: (0)(19)tele/sonoff_bad/LWTOnline
2019.01.30 16:26:53 4: myMqttServer_172.16.1.205_49209 DVES_C1EB89 PUBLISH tele/sonoff_bad/LWT:Online
2019.01.30 16:26:53 5: myMqttServer: dispatch autocreate:DVES_C1EB89:tele/sonoff_bad/LWT:Online
2019.01.30 16:26:53 4: Closing second connection for DVES_C1EB89/172.16.1.205 without lwt
2019.01.30 16:26:53 4: Connection closed for myMqttServer_172.16.1.205_49208: EOF
2019.01.30 16:26:53 5: PUBLISH: (0)(21)cmnd/sonoff_bad/POWER
2019.01.30 16:26:53 4: myMqttServer_172.16.1.205_49209 DVES_C1EB89 PUBLISH cmnd/sonoff_bad/POWER:
2019.01.30 16:26:53 5: myMqttServer: dispatch autocreate:DVES_C1EB89:cmnd/sonoff_bad/POWER:
2019.01.30 16:26:53 5: SUBSCRIBE: (0)(2)(0)(17)cmnd/sonoff_bad/#(0)
2019.01.30 16:26:53 4: myMqttServer_172.16.1.205_49209 DVES_C1EB89 SUBSCRIBE
2019.01.30 16:26:53 4:   topic:cmnd/sonoff_bad/# qos:0
2019.01.30 16:26:53 5: SUBSCRIBE: (0)(3)(0)(14)cmnd/sonoffs/#(0)
2019.01.30 16:26:53 4: myMqttServer_172.16.1.205_49209 DVES_C1EB89 SUBSCRIBE
2019.01.30 16:26:53 4:   topic:cmnd/sonoffs/# qos:0
2019.01.30 16:26:53 5: SUBSCRIBE: (0)(4)(0)(21)cmnd/DVES_C1EB89_fb/#(0)
2019.01.30 16:26:53 4: myMqttServer_172.16.1.205_49209 DVES_C1EB89 SUBSCRIBE
2019.01.30 16:26:53 4:   topic:cmnd/DVES_C1EB89_fb/# qos:0

rudolfkoenig · 31 Januar 2019, 07:58:52

Zitat2019.01.30 16:26:53 4: Closing second connection for DVES_C1EB89/172.16.1.205 without lwt

Das ist eine Besonderheit des Sonoffs (oder war das Tasmota / ESP8266?), dass eine zweite Verbindung goeffnet wird, obwohl eine schon besteht.
Warum das Geraet das tut (schlechte Verbindung, Bug, etc), weiss ich nicht, sorgt aber fuer eine kurzfristig geaenderte Anzahl an Verbindungen.

BeetleX · 31 Januar 2019, 08:51:24

OK, ich schaue dort mal nach,
Danke