Ständige Verbindungsabbrüche bei MQTT2

Reinerlein · 24 Juli 2020, 11:54:37

Hi Rudi,

im Anhang mal das Log... ich habe davor ein Log für Calling und danach ein Log für Calling-End eingebaut. Das steht also direkt um den NotifyFn-Aufruf herum.

Grüße
Reinerlein

P.S.: Achtung, die Datei ist entpackt 12MB groß...

rudolfkoenig · 24 Juli 2020, 13:42:38

Ich sehe pro Event ca 150 (sinnlose) Aufrufe, jeweils mit ca 0.2ms, macht in Summe ca 30ms.
Dabei sind aber auch 2 WEB_Default Anrufe, die jeweils ca 30ms brauchen.

- es wundert mich, dass in deinem Fall die Filterung der notifies so schlecht funktioniert. Wie schauen deine Regexps aus? Z.Bsp. fuer wohnzimmer_TasterTerrasse_6_Notify_Short oder flur_Taster_Notify?
- die 2 WEB-Notifies klingen nach "Wandtablet". Kannst Du mehr dazu sagen?

Reinerlein · 24 Juli 2020, 14:40:00

Hi Rudi,

die WEB-Teile kommen daher, das ich mehrere Browserfenster offen hatte, um zügig die verbose-Einstellungen ändern zu können...

Diese Notifies sehen eigentlich normal aus:
wohnzimmer_TasterTerrasse_6_Notify_Short

Code Auswählen

 Internals:
   DEF        wohnzimmer_TasterTerrasse_6.Short.* set garten_Beleuchtung_LightScene scene myOn
   FUUID      5d84d3a1-f33f-6779-19b5-aa2baffbc9977f48
   NAME       wohnzimmer_TasterTerrasse_6_Notify_Short
   NR         1020
   NTFY_ORDER 50-wohnzimmer_TasterTerrasse_6_Notify_Short
   REGEXP     wohnzimmer_TasterTerrasse_6.Short.*
   STATE      active
   TYPE       notify
   READINGS:
     2020-07-24 11:20:10   state           active
Attributes:

flur_Taster_Notify

Code Auswählen

 Internals:
   DEF        flur_Taster set vorgarten_Gehweg on-for-timer 300
   FUUID      5d84d3a0-f33f-6779-86a6-2666224ad2c84a4c
   NAME       flur_Taster_Notify
   NR         409
   NTFY_ORDER 50-flur_Taster_Notify
   REGEXP     flur_Taster
   STATE      active
   TYPE       notify
   READINGS:
     2020-07-24 11:20:10   state           active
Attributes:

Ich habe auch einige auf der Notify-Liste gesehen, die eigentlich sehr genau definiert sind. Hauptsächlich Lightscene, wo ja jedes Device im Define angegeben wird oder auch Max-Devices. Und natürlich ein Haufen FileLog-Devices...
Es scheint so zu sein, dass einige Module "NOTIFYDEV" nicht setzen. In diesen Fällen taucht das dann hier auf der Device-Unbestimmten-Liste auf.
Das muss wohl jedes Modul selber machen... leider scheinen das einige Module, die auch noch oft in einer Installation genutzt werden, nicht zu tun...

Grüße
Reinerlein

rudolfkoenig · 24 Juli 2020, 17:26:28

ZitatDiese Notifies sehen eigentlich normal aus:

Normal schon, leider erkennt fhem.pl nicht das Geraet: es gibt kein NOTIFYDEV Internal.
Um es zu erkennen, muesste es "wohnzimmer_TasterTerrasse_6:Short.* heissen, weil : als Trenner zwischen Geraetename und Event dient, und notifyRegexpChanged das : braucht, um ein Geraet zu erkennen.

Um das bessere Regexp einfacher zu finden habe ich eine Funktion notifyRegexpCheck eingecheckt, hier sind ein paar Beispiele.
Die Testinstallation kennt mehrere Geraete die mit s300 anfangen und wz.

Code Auswählen


fhem> { notifyRegexpCheck('s300th_og') }
s300th_og: device s300th_og (OK)

fhem> { notifyRegexpCheck('s300.*T.*') }
s300.*T.*: no match (ignored)

fhem> { notifyRegexpCheck('s300.*:T.*') }
s300.*:T.*: devspec s300th_2,s300th_dach,s300th_keller,s300th_kueche,s300th_og (OK)

fhem> { notifyRegexpCheck('s300.*:T.*|wz.*temperature.*') }
s300.*:T.*: devspec s300th_2,s300th_dach,s300th_keller,s300th_kueche,s300th_og (OK)
wz.*temperature.*: no match (ignored)

fhem> { notifyRegexpCheck('(s300.*:T|wz:temperature).*') }
(s300.*:T: devspec s300th_2,s300th_dach,s300th_keller,s300th_kueche,s300th_og (OK)
wz:temperature).*: device wz (OK)

Reinerlein · 24 Juli 2020, 18:15:29

Hi Rudi,

ok, danke für den Tipp, dann baue ich das mal entsprechend um.
Vielleicht sollte man in der Doku darauf hinweisen. Für mich waren die beiden Varianten equivalent... zumal ja beides funktioniert...

Aber auch da habe ich gerade ein Device gefunden, wo es eigentlich korrekt drinsteht, aber trotzdem kein notifydev gesetzt wurde:

Code Auswählen

 Internals:
   DEF        /opt/fhem/log/garten_Regensensor_Rain-%Y-%m.log garten_Regensensor_Heating:state:.(on|off)|garten_Regensensor_Rain:state:.*|garten_Regensensor_Rain:stateNumber:.*
   FD         161
   FUUID      5d84d3b9-f33f-6779-51d7-4f0a7d65a282a433
   NAME       FileLog_garten_Regensensor_Rain
   NR         1522
   NTFY_ORDER 50-FileLog_garten_Regensensor_Rain
   REGEXP     garten_Regensensor_Heating:state:.(on|off)|garten_Regensensor_Rain:state:.*|garten_Regensensor_Rain:stateNumber:.*
   STATE      active
   TYPE       FileLog
   currentlogfile /opt/fhem/log/garten_Regensensor_Rain-2020-07.log
   logfile    /opt/fhem/log/garten_Regensensor_Rain-%Y-%m.log
   READINGS:
     2020-07-24 17:59:46   linesInTheFile  2528
Attributes:
   addStateEvent 1

Da kämen halt zwei Devices rein:

Code Auswählen

garten_Regensensor_Heating,garten_Regensensor_Rain

Muss man noch was anderes beachten?

Grüße
Reinerlein

Reinerlein · 24 Juli 2020, 18:33:46

Hi Rudi,

außerdem habe einige Regexp in dem Stil:

Code Auswählen



Internals:
   DEF        /opt/fhem/log/hwr_WasserTemperatur-%Y-%m.log hwr_WasserTemperatur:(temperature|diffTemp).*
   FD         15
   FUUID      5d84d3a0-f33f-6779-cd4b-a739785e66630cd0
   NAME       FileLog_hwr_WasserTemperatur
   NR         222
   NTFY_ORDER 50-FileLog_hwr_WasserTemperatur
   REGEXP     hwr_WasserTemperatur:(temperature|diffTemp).*
   STATE      active
   TYPE       FileLog
   currentlogfile /opt/fhem/log/hwr_WasserTemperatur-2020-07.log
   logfile    /opt/fhem/log/hwr_WasserTemperatur-%Y-%m.log
   READINGS:
     2020-07-24 18:29:18   linesInTheFile  27263
Attributes:
   logtype    myWaterTemp:Temp,text

Das verwende ich gerne, wenn ich mehrere Readings eines Devices matchen möchte...

Grüße
Reinerlein

rudolfkoenig · 24 Juli 2020, 18:49:25

Mit der neuen Funktion sieht man, wie fhem.pl "denkt":

Code Auswählen

fhem> { notifyRegexpCheck('garten_Regensensor_Heating:state:.(on|off)|garten_Regensensor_Rain:state:.*|garten_Regensensor_Rain:stateNumber:.*') }
garten_Regensensor_Heating:state:.(on: device garten_Regensensor_Heating (OK)
off): unknown (ignored)
garten_Regensensor_Rain:state:.*: device garten_Regensensor_Rain (OK)
garten_Regensensor_Rain:stateNumber:.*: device garten_Regensensor_Rain (OK)

Damit NOTIFYDEV angelegt wird, muss (on|off) entweder samt device verdoppelt werden, oder als o[nf]+ geschrieben werden, oder...
NOTIFYDEV ist kein _muss_, es ermoeglich aber fhem.pl eine Optimierung vorzunehmen.

Nestor · 02 August 2020, 15:24:29

There is a small bug in notifyRegexpCheck when devspec2array returns a single item. Also avoids PERL WARNING "isn't numeric".

Code Auswählen

fhem> {devspec2array 'Rt_EnO.+'}
1
fhem> {notifyRegexpCheck 'Rt_EnO.+' }
Rt_EnO.+: unknown (ignored)

Patch:

Code Auswählen

@@ -5418,7 +5426,7 @@
       "$_: device $1 (OK)";
     } else {
       my @ds = devspec2array($1);
-      if(@ds > 1 || $ds[0] != $1) {
+      if(@ds > 1 || $ds[0] ne $1) {
         "$_: devspec ".join(",",@ds)." (OK)";
       } else {
         "$_: unknown (ignored)";

I suppose @ds > 1 is also not necessary.

rudolfkoenig · 02 August 2020, 16:28:20

Thanks, Patch applied.

xenos1984 · 13 August 2020, 07:55:09

Seit einem Update vor ein paar Tagen habe ich nun das Problem, dass sich meine MQTT Clients ständig neu anmelden, und zwar immer dann, wenn der FHEM-Prozess unter hoher Last fährt (Rendern von mehreren SVG-Plots oder Rastern skalierter SVG-Icons für einen RSS Feed), und dann für eine Weile auf 100% CPU läuft. So weit ich sehen kann, gab es da diese Änderung:

http://svn.fhem.de/trac/changeset/22454/trunk/fhem/FHEM/00_MQTT2_SERVER.pm

Könnte die das Phänomen verursachen?

List vom MQTT2_SERVER:

Code Auswählen

Internals:
   CONNECTS   24063
   DEF        1883 global
   FD         8
   FUUID      5e2b233f-f33f-edb2-bdca-36d41dc0d88c567e
   NAME       mqtt
   NR         43
   PORT       1883
   STATE      Initialized
   TYPE       MQTT2_SERVER
   READINGS:
     2020-08-13 07:49:25   RETAIN          {"cmd/climate/bedroom/backlight":"0","cmd/climate/bedroom/mode":"R","cmd/climate/bedroom/radiator":"0","cmd/climate/bedroom/setpoint":"24.6","cmd/climate/bedroom/tolerance":"0.1","cmd/climate/main/backlight":"0","cmd/climate/main/mode":"L","cmd/climate/main/radiator1":"0","cmd/climate/main/radiator2":"1","cmd/climate/main/setpoint":"30.0","cmd/climate/main/tolerance":"0.1","cmd/climate/server/backlight":"0","status/climate/bedroom/arduino":"1","status/climate/main/arduino":"1","status/climate/server/arduino":"1"}
     2020-05-02 16:58:44   lastPublish     status/server/climate/arduino:
     2020-08-13 08:43:02   nrclients       54
     2020-08-10 13:10:58   state           Initialized
   clients:
     mqtt_192.168.1.116_58005 1
     mqtt_192.168.1.117_58005 1
     mqtt_192.168.1.119_57967 1
   retain:
     cmd/climate/bedroom/backlight:
       ts         1597054259.15503
       val        0
     cmd/climate/bedroom/mode:
       ts         1597054259.15503
       val        R
     cmd/climate/bedroom/radiator:
       ts         1597054259.15503
       val        0
     cmd/climate/bedroom/setpoint:
       ts         1597054259.15503
       val        24.6
     cmd/climate/bedroom/tolerance:
       ts         1597054259.15503
       val        0.1
     cmd/climate/main/backlight:
       ts         1597054259.15503
       val        0
     cmd/climate/main/mode:
       ts         1597054259.15503
       val        L
     cmd/climate/main/radiator1:
       ts         1597054259.15503
       val        0
     cmd/climate/main/radiator2:
       ts         1597054259.15503
       val        1
     cmd/climate/main/setpoint:
       ts         1597054259.15503
       val        30.0
     cmd/climate/main/tolerance:
       ts         1597054259.15503
       val        0.1
     cmd/climate/server/backlight:
       ts         1597054259.15503
       val        0
     status/climate/bedroom/arduino:
       ts         1597294164.97552
       val        1
     status/climate/main/arduino:
       ts         1597294165.02614
       val        1
     status/climate/server/arduino:
       ts         1597294165.00912
       val        1
Attributes:
   autocreate no
   icon       it_i-net
   room       System->Interfaces

Ein MQTT2_DEVICE:

Code Auswählen

Internals:
   DEVICETOPIC climate_server
   FUUID      5ea5ae48-f33f-edb2-3a37-084c09f683aed438
   IODev      mqtt
   LASTInputDev mqtt
   MSGCNT     68079
   NAME       climate_server
   NR         48
   STATE      1:online
2:ok
3:off
<br>
28.8&deg;C
35.0&percnt;
   TYPE       MQTT2_DEVICE
   mqtt_MSGCNT 68079
   mqtt_TIME  2020-08-13 08:45:09
   READINGS:
     2020-08-13 08:44:59   absoluteHumidity 9.9
     2020-08-13 07:49:25   arduino         online
     2020-08-13 07:49:26   backlight       off
     2020-08-13 08:44:59   dewpoint        11.8
     2020-08-13 08:45:09   humidity        35.0
     2020-06-05 01:15:26   state           backlight
     2020-08-13 08:45:09   temperature     28.8
     2020-08-13 08:45:09   valid           ok
     2020-08-13 08:44:59   vapourPressure  13.8
Attributes:
   IODev      mqtt
   devStateIcon 1.online:arduino@green 1.offline:arduino@red 2.ok:temperature_humidity@green 2.error:temperature_humidity@red 3.on:light_light_dim_100@orange:backlight+off 3.off:light_light_dim_00@black:backlight+on
   event-on-change-reading .*
   icon       sani_heating_temp
   readingList status/climate/server/arduino:.* {{"arduino" => ($EVTPART0 ? "online" : "offline")}}
status/climate/server/humidity:.* humidity
status/climate/server/temperature:.* temperature
status/climate/server/valid:.* {{"valid" => ($EVTPART0 ? "ok" : "error")}}
status/climate/server/backlight:.* {{"backlight" => ($EVTPART0 ? "on" : "off")}}
   room       Rooms->Server,Sensors->Climate
   setList    backlight:on,off {"cmd/climate/server/backlight:r " . ($EVTPART1 eq "on" ? 1 : 0)}
   stateFormat 1:arduino
2:valid
3:backlight
<br>
temperature&deg;C
humidity&percnt;

Log-Auszug:

Code Auswählen

2020.08.13 08:49:49 4: Connection accepted from mqtt_192.168.1.119_59750
2020.08.13 08:49:50 4: Connection accepted from mqtt_192.168.1.117_59486
2020.08.13 08:49:50 5: in:  CONNECT: (16)<(0)(4)MQTT(4)&(0)(15)(0)(14)arduino_server(0)(29)status/climate/server/arduino(0)(1)0
2020.08.13 08:49:50 4:   mqtt_192.168.1.119_59750 cid:arduino_server CONNECT V:4 keepAlive:15 LWT:status/climate/server/arduino:0
2020.08.13 08:49:50 5: out: CONNACK:  (2)(0)(0)
2020.08.13 08:49:50 5: in:  CONNECT: (16)8(0)(4)MQTT(4)&(0)(15)(0)(12)arduino_main(0)(27)status/climate/main/arduino(0)(1)0
2020.08.13 08:49:50 4:   mqtt_192.168.1.117_59486 cid:arduino_main CONNECT V:4 keepAlive:15 LWT:status/climate/main/arduino:0
2020.08.13 08:49:50 5: out: CONNACK:  (2)(0)(0)
2020.08.13 08:49:50 4: Connection accepted from mqtt_192.168.1.116_58006
2020.08.13 08:49:50 5: in:  CONNECT: (16)>(0)(4)MQTT(4)&(0)(15)(0)(15)arduino_bedroom(0)(30)status/climate/bedroom/arduino(0)(1)0
2020.08.13 08:49:50 4:   mqtt_192.168.1.116_58006 cid:arduino_bedroom CONNECT V:4 keepAlive:15 LWT:status/climate/bedroom/arduino:0
2020.08.13 08:49:50 5: out: CONNACK:  (2)(0)(0)
2020.08.13 08:49:50 5: in:  PUBLISH: 1(30)(0)(27)status/climate/main/arduino1
2020.08.13 08:49:50 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/arduino:1
2020.08.13 08:49:50 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/arduino\0001
2020.08.13 08:49:51 5: in:  SUBSCRIBE: (130)(23)(0)(2)(0)(18)cmd/climate/main/+(0)
2020.08.13 08:49:51 4:   mqtt_192.168.1.117_59486 arduino_main SUBSCRIBE
2020.08.13 08:49:51 4:   topic:cmd/climate/main/+ qos:0
2020.08.13 08:49:51 5: out: SUBACK: (144)(3)(0)(2)(1)
2020.08.13 08:49:51 5: in:  PUBLISH: 0"(0)(28)status/climate/main/humidity43.5
2020.08.13 08:49:51 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/humidity:43.5
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/humidity\00043.5
2020.08.13 08:49:51 5: in:  PUBLISH: 0%(0)(31)status/climate/main/temperature24.3
2020.08.13 08:49:51 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/temperature:24.3
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/temperature\00024.3
2020.08.13 08:49:51 5: in:  PUBLISH: 0(28)(0)(25)status/climate/main/valid1
2020.08.13 08:49:51 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/valid:1
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/valid\0001
2020.08.13 08:49:51 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator11
2020.08.13 08:49:51 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator1:1
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator1\0001
2020.08.13 08:49:51 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator21
2020.08.13 08:49:51 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator2:1
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator2\0001
2020.08.13 08:49:51 5: in:  PUBLISH: 1!(0)(30)status/climate/bedroom/arduino1
2020.08.13 08:49:51 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/arduino:1
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/arduino\0001
2020.08.13 08:49:51 5: in:  SUBSCRIBE: (130)(26)(0)(2)(0)(21)cmd/climate/bedroom/+(0)
2020.08.13 08:49:51 4:   mqtt_192.168.1.116_58006 arduino_bedroom SUBSCRIBE
2020.08.13 08:49:51 4:   topic:cmd/climate/bedroom/+ qos:0
2020.08.13 08:49:51 5: out: SUBACK: (144)(3)(0)(2)(1)
2020.08.13 08:49:51 5: in:  PUBLISH: 0%(0)(31)status/climate/bedroom/humidity46.0
2020.08.13 08:49:51 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/humidity:46.0
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/humidity\00046.0
2020.08.13 08:49:51 5: in:  PUBLISH: 0((0)"status/climate/bedroom/temperature25.1
2020.08.13 08:49:51 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/temperature:25.1
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/temperature\00025.1
2020.08.13 08:49:51 5: in:  PUBLISH: 0(31)(0)(28)status/climate/bedroom/valid1
2020.08.13 08:49:51 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/valid:1
2020.08.13 08:49:51 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/valid\0001
2020.08.13 08:49:52 5:   mqtt_192.168.1.117_59486 arduino_main => cmd/climate/main/tolerance:0.1
2020.08.13 08:49:52 5: out: PUBLISH: 0(31)(0)(26)cmd/climate/main/tolerance0.1
2020.08.13 08:49:52 5:   mqtt_192.168.1.117_59486 arduino_main => cmd/climate/main/radiator2:1
2020.08.13 08:49:52 5: out: PUBLISH: 0(29)(0)(26)cmd/climate/main/radiator21
2020.08.13 08:49:52 5:   mqtt_192.168.1.117_59486 arduino_main => cmd/climate/main/backlight:0
2020.08.13 08:49:52 5: out: PUBLISH: 0(29)(0)(26)cmd/climate/main/backlight0
2020.08.13 08:49:52 5:   mqtt_192.168.1.117_59486 arduino_main => cmd/climate/main/mode:L
2020.08.13 08:49:52 5: out: PUBLISH: 0(24)(0)(21)cmd/climate/main/modeL
2020.08.13 08:49:52 5:   mqtt_192.168.1.117_59486 arduino_main => cmd/climate/main/setpoint:30.0
2020.08.13 08:49:52 5: out: PUBLISH: 0(31)(0)(25)cmd/climate/main/setpoint30.0
2020.08.13 08:49:52 5:   mqtt_192.168.1.117_59486 arduino_main => cmd/climate/main/radiator1:0
2020.08.13 08:49:52 5: out: PUBLISH: 0(29)(0)(26)cmd/climate/main/radiator10
2020.08.13 08:49:52 5:   mqtt_192.168.1.116_58006 arduino_bedroom => cmd/climate/bedroom/backlight:0
2020.08.13 08:49:52 5: out: PUBLISH: 0 (0)(29)cmd/climate/bedroom/backlight0
2020.08.13 08:49:52 5:   mqtt_192.168.1.116_58006 arduino_bedroom => cmd/climate/bedroom/radiator:0
2020.08.13 08:49:52 5: out: PUBLISH: 0(31)(0)(28)cmd/climate/bedroom/radiator0
2020.08.13 08:49:52 5:   mqtt_192.168.1.116_58006 arduino_bedroom => cmd/climate/bedroom/setpoint:24.6
2020.08.13 08:49:52 5: out: PUBLISH: 0"(0)(28)cmd/climate/bedroom/setpoint24.6
2020.08.13 08:49:52 5:   mqtt_192.168.1.116_58006 arduino_bedroom => cmd/climate/bedroom/tolerance:0.1
2020.08.13 08:49:52 5: out: PUBLISH: 0"(0)(29)cmd/climate/bedroom/tolerance0.1
2020.08.13 08:49:52 5:   mqtt_192.168.1.116_58006 arduino_bedroom => cmd/climate/bedroom/mode:R
2020.08.13 08:49:52 5: out: PUBLISH: 0(27)(0)(24)cmd/climate/bedroom/modeR
2020.08.13 08:49:52 5: in:  PUBLISH: 0"(0)(29)status/climate/main/tolerance0.1
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/tolerance:0.1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/tolerance\0000.1
2020.08.13 08:49:52 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator11
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator1:1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator1\0001
2020.08.13 08:49:52 5: in:  PUBLISH: 0#(0) status/climate/bedroom/backlight0
2020.08.13 08:49:52 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/backlight:0
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/backlight\0000
2020.08.13 08:49:52 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator21
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator2:1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator2\0001
2020.08.13 08:49:52 5: in:  PUBLISH: 0"(0)(31)status/climate/bedroom/radiator0
2020.08.13 08:49:52 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/radiator:0
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/radiator\0000
2020.08.13 08:49:52 5: in:  PUBLISH: 0%(0)(31)status/climate/bedroom/setpoint24.6
2020.08.13 08:49:52 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/setpoint:24.6
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/setpoint\00024.6
2020.08.13 08:49:52 5: in:  PUBLISH: 0 (0)(29)status/climate/main/backlight0
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/backlight:0
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/backlight\0000
2020.08.13 08:49:52 5: in:  PUBLISH: 0(27)(0)(24)status/climate/main/modeL
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/mode:L
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/mode\000L
2020.08.13 08:49:52 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator11
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator1:1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator1\0001
2020.08.13 08:49:52 5: in:  PUBLISH: 0%(0) status/climate/bedroom/tolerance0.1
2020.08.13 08:49:52 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/tolerance:0.1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/tolerance\0000.1
2020.08.13 08:49:52 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator21
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator2:1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator2\0001
2020.08.13 08:49:52 5: in:  PUBLISH: 0(30)(0)(27)status/climate/bedroom/modeR
2020.08.13 08:49:52 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/mode:R
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/mode\000R
2020.08.13 08:49:52 5: in:  PUBLISH: 0"(0)(31)status/climate/bedroom/radiator0
2020.08.13 08:49:52 4:   mqtt_192.168.1.116_58006 arduino_bedroom PUBLISH status/climate/bedroom/radiator:0
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/radiator\0000
2020.08.13 08:49:52 5: in:  PUBLISH: 0"(0)(28)status/climate/main/setpoint30.0
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/setpoint:30.0
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/setpoint\00030.0
2020.08.13 08:49:52 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator11
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator1:1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator1\0001
2020.08.13 08:49:52 5: in:  PUBLISH: 0 (0)(29)status/climate/main/radiator21
2020.08.13 08:49:52 4:   mqtt_192.168.1.117_59486 arduino_main PUBLISH status/climate/main/radiator2:1
2020.08.13 08:49:52 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/radiator2\0001
2020.08.13 08:49:53 4: Connection accepted from mqtt_192.168.1.119_57967
2020.08.13 08:49:53 5: in:  CONNECT: (16)<(0)(4)MQTT(4)&(0)(15)(0)(14)arduino_server(0)(29)status/climate/server/arduino(0)(1)0
2020.08.13 08:49:53 4:   mqtt_192.168.1.119_57967 cid:arduino_server CONNECT V:4 keepAlive:15 LWT:status/climate/server/arduino:0
2020.08.13 08:49:53 5: out: CONNACK:  (2)(0)(0)
2020.08.13 08:49:53 5: in:  PUBLISH: 1 (0)(29)status/climate/server/arduino1
2020.08.13 08:49:53 4:   mqtt_192.168.1.119_57967 arduino_server PUBLISH status/climate/server/arduino:1
2020.08.13 08:49:53 5: mqtt: dispatch autocreate=no\000arduino_server\000status/climate/server/arduino\0001
2020.08.13 08:49:53 5: in:  SUBSCRIBE: (130)(25)(0)(2)(0)(20)cmd/climate/server/+(0)
2020.08.13 08:49:53 4:   mqtt_192.168.1.119_57967 arduino_server SUBSCRIBE
2020.08.13 08:49:53 4:   topic:cmd/climate/server/+ qos:0
2020.08.13 08:49:53 5: out: SUBACK: (144)(3)(0)(2)(1)
2020.08.13 08:49:53 5: in:  PUBLISH: 0$(0)(30)status/climate/server/humidity34.9
2020.08.13 08:49:53 4:   mqtt_192.168.1.119_57967 arduino_server PUBLISH status/climate/server/humidity:34.9
2020.08.13 08:49:53 5: mqtt: dispatch autocreate=no\000arduino_server\000status/climate/server/humidity\00034.9
2020.08.13 08:49:53 5: in:  PUBLISH: 0'(0)!status/climate/server/temperature28.8
2020.08.13 08:49:53 4:   mqtt_192.168.1.119_57967 arduino_server PUBLISH status/climate/server/temperature:28.8
2020.08.13 08:49:53 5: mqtt: dispatch autocreate=no\000arduino_server\000status/climate/server/temperature\00028.8
2020.08.13 08:49:53 5: in:  PUBLISH: 0(30)(0)(27)status/climate/server/valid1
2020.08.13 08:49:53 4:   mqtt_192.168.1.119_57967 arduino_server PUBLISH status/climate/server/valid:1
2020.08.13 08:49:53 5: mqtt: dispatch autocreate=no\000arduino_server\000status/climate/server/valid\0001
2020.08.13 08:50:26 5:   mqtt_192.168.1.119_57967 arduino_server => cmd/climate/server/backlight:0
2020.08.13 08:50:26 5: out: PUBLISH: 0(31)(0)(28)cmd/climate/server/backlight0
2020.08.13 08:50:26 3: mqtt: mqtt_192.168.1.119_59750/arduino_server left us (keepalive check)
2020.08.13 08:50:26 4: Closing second connection for arduino_server/192.168.1.119 without lwt
2020.08.13 08:50:26 3: mqtt: mqtt_192.168.1.116_58006/arduino_bedroom left us (keepalive check)
2020.08.13 08:50:26 5: mqtt: dispatch autocreate=no\000arduino_bedroom\000status/climate/bedroom/arduino\0000
2020.08.13 08:50:26 3: mqtt: mqtt_192.168.1.119_57967/arduino_server left us (keepalive check)
2020.08.13 08:50:26 5: mqtt: dispatch autocreate=no\000arduino_server\000status/climate/server/arduino\0000
2020.08.13 08:50:26 3: mqtt: mqtt_192.168.1.117_59486/arduino_main left us (keepalive check)
2020.08.13 08:50:26 5: mqtt: dispatch autocreate=no\000arduino_main\000status/climate/main/arduino\0000

rudolfkoenig · 13 August 2020, 09:39:37

Dass die verlinkte Aenderung das Problem verursacht, ist zwar moeglich, aber nur bei einem blockierten System, und dann je nach Glueck und Umgebung funktioniert die alte oder die neue Methode besser. Ich habe noch meinen Zweifel daran, dass die Ursache des gemeldeten Problems diese Aenderung ist.

Ich sehe im Log keine Hinweise fuer eine Blockierung, evtl. hilft da "attr global verbose 5". Das einzige "Problem" im Log ist eine "keepalive check / left us", allerdings kommt das erst, nachdem das gleiche Geraet 30 Sekunden vorher eine zweite Verbindung aufgebaut hat, was bei "kaputten" WLAN oefters beobachtet wurde.

Falls man ein Blockieren des Systems beobachtet, dann sollte man das natuerlich fixen, z.Bsp. indem Plots mit "attr WEB plotEmbed 2" oder "attr WEB plotfork 1" in einem geforkten Prozess berechnet.

xenos1984 · 13 August 2020, 10:09:35

Zitat von: rudolfkoenig am 13 August 2020, 09:39:37
Ich sehe im Log keine Hinweise fuer eine Blockierung, evtl. hilft da "attr global verbose 5". Das einzige "Problem" im Log ist eine "keepalive check / left us", allerdings kommt das erst, nachdem das gleiche Geraet 30 Sekunden vorher eine zweite Verbindung aufgebaut hat, was bei "kaputten" WLAN oefters beobachtet wurde.

Mein Verdacht kommt u.a. daher, dass das Problem seit einem Update vor ein paar Tagen auftritt - davor war nichts dergleichen festzustellen, obwohl die CPU-Last gleich war. Deshalb hatte ich die Vermutung, dass durch die Methode mit InternalTimer in dem Fall die Kommunikation so lange verzögert bzw. der Timer so spät ausgelöst wird, dass der Client inzwischen einen Timeout feststellt und sich neu verbindet.

Zitat
Falls man ein Blockieren des Systems beobachtet, dann sollte man das natuerlich fixen, z.Bsp. indem Plots mit "attr WEB plotEmbed 2" oder "attr WEB plotfork 1" in einem geforkten Prozess berechnet.

Das werde ich auf jeden Fall versuchen. Wirkt sich das denn auch auf die Erzeugung von PNG Grafiken im RSS-Modul aus (und zwar nicht auf das Einbinden von SVG-Plots in PNG-Grafiken, sondern Icons, Text etc.). Bei SVG-Plots hatte ich schon vorher plotfork auf 1, nun versuche ich es auch mit plotEmbed auf 2. Beide führen noch zu anderen Problemen, aber die poste ich im SVG-Bereich, weil sie nicht zu diesem Thema passen.

xenos1984 · 18 August 2020, 16:19:47

Inzwischen habe ich die Ursache ausfindig machen können, weshalb FHEM bei mir für bis zu 30 Sekunden hängt und die Timeouts auftreten. Es handelt sich dabei um das RSS-Modul. Und zwar hatte ich in einem Feed zwei Laptop-Icons, und anscheinend braucht Perl so lange, um die von SVG nach PNG zu konvertieren. Wenn ich die beiden durch andere ersetze, dauert es wenige Sekunden und das PNG erscheint. Da gibt es auch keine Verbindungsabbrüche mehr.

Vielleicht könnte man die Erzeugung von RSS-Feeds ähnlich wie die SVG-Plots optional über Fork auslagern, falls man doch mal etwas komplexeres rendern möchte... Ich werde das mal in einem eigenen Thread im entsprechenden Forum anregen.