define notify: kurzzeitig keine Daten (S7) in FHEM einlesen

[martin2day]

Hallo zusammen,

seit dem Update beobachte ich ein eher seltsames Verhalten von FHEM wo ich gern einen Rat hören würde.
Den Hinweis habe ich bereits gelesen.

Ich programmiere derzeit einige Sachen weiter. Dabei ist mir aufgefallen, wenn ich ein neues notify anlege, bekomme ich für eine bestimmte Zeit keine Aktualisierungen von den Modulen S7Read und HmUART. Nach einer Wartezeit von einigen Minuten funktioniert alles wieder.
Es werden nur die lesenden Verbindungen zu FHEM blockiert, Daten aus FHEM herausfinden funktioniert.
Ich habe verbose auf 5 gestellt und ich hänge den Log nach dem erstellen des notifys mal mit an:

Code Auswählen Erweitern

2017.02.21 14:10:33 4: WEB_192.168.10.151_61247 GET /fhem?XHR=1&inform=type=status;filter=WifiRadio_BadOG;since=1487682632;fmt=JSON&fw_id=894×tamp=1487682633657; BUFLEN:0
2017.02.21 14:11:08 4: Connection closed for WEB_192.168.10.151_61247: EOF
2017.02.21 14:11:08 4: WEB_192.168.10.151_61248 POST /fhem&fw_id=894&fwcsrf=fhem_899806616775050&cmd=define+n_S7Radio_BadOG_Senderwahl+notify+S7Radio_BadOG_Senderwahl.on+set+WifiRadio_BadOG+next; BUFLEN:0
2017.02.21 14:11:08 4: Connection closed for WEB_192.168.10.151_61210: Connection reset by peer
2017.02.21 14:11:08 4: WEB_192.168.10.151_61248 GET /fhem?detail=n_S7Radio_BadOG_Senderwahl&fw_id=894; BUFLEN:0
2017.02.21 14:11:09 4: name: /fhem?detail=n_S7Radio_BadOG_Senderwahl&fw_id=894 / RL:9888 / text/html; charset=UTF-8 / Content-Encoding: gzip
/
2017.02.21 14:11:09 4: WEB_192.168.10.151_61248 GET /fhem?cmd={ReadingsVal(%22n_S7Radio_BadOG_Senderwahl%22,%22ActionDetector%22,%22%22)}&XHR=1&fwcsrf=fhem_899806616775050; BUFLEN:0
2017.02.21 14:11:09 4: name: /fhem?cmd={ReadingsVal(%22n_S7Radio_BadOG_Senderwahl%22,%22ActionDetector%22,%22%22)}&XHR=1&fwcsrf=fhem_899806616775050 / RL:21 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2017.02.21 14:11:09 4: Connection accepted from WEB_192.168.10.151_61251
2017.02.21 14:11:09 4: Connection accepted from WEB_192.168.10.151_61252
2017.02.21 14:11:09 4: WEB_192.168.10.151_61252 GET /fhem?cmd={AttrVal(%22n_S7Radio_BadOG_Senderwahl%22,%22room%22,%22%22)}&XHR=1&fwcsrf=fhem_899806616775050; BUFLEN:0
2017.02.21 14:11:09 4: name: /fhem?cmd={AttrVal(%22n_S7Radio_BadOG_Senderwahl%22,%22room%22,%22%22)}&XHR=1&fwcsrf=fhem_899806616775050 / RL:21 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2017.02.21 14:11:09 4: WEB_192.168.10.151_61251 GET /fhem?cmd={ReadingsVal(%22n_S7Radio_BadOG_Senderwahl%22,%22active%22,%22%22)}&XHR=1&fwcsrf=fhem_899806616775050; BUFLEN:0
2017.02.21 14:11:09 4: name: /fhem?cmd={ReadingsVal(%22n_S7Radio_BadOG_Senderwahl%22,%22active%22,%22%22)}&XHR=1&fwcsrf=fhem_899806616775050 / RL:21 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2017.02.21 14:11:09 4: WEB_192.168.10.151_61248 GET /fhem?XHR=1&inform=type=status;filter=n_S7Radio_BadOG_Senderwahl;since=1487682668;fmt=JSON&fw_id=894×tamp=1487682669289; BUFLEN:0
2017.02.21 14:11:10 4: WEB_192.168.10.151_61252 POST /fhem?cmd=save&fwcsrf=fhem_899806616775050&XHR=1&fw_id=894; BUFLEN:0
2017.02.21 14:11:10 4: name: /fhem?cmd=save&fwcsrf=fhem_899806616775050&XHR=1&fw_id=894 / RL:52 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2017.02.21 14:11:13 4: Connection closed for WEB_192.168.10.151_61248: EOF
2017.02.21 14:11:13 4: WEB_192.168.10.151_61252 GET /fhem?room=Multimedia; BUFLEN:0
2017.02.21 14:11:13 4: name: /fhem?room=Multimedia / RL:16858 / text/html; charset=UTF-8 / Content-Encoding: gzip

Ich hoffe mir kann geholfen werden.
Ich bitte um Hilfe.

Vielen Dank
Martin

[Thorsten Pferdekaemper]

Hi,
tja...
Das Erstellen des notify selbst sieht man im Log meiner Meinung nach nicht. Hast Du bestimmt global verbose auf 5 oder nur FHEMWEB verbose?
Außerdem:

Es werden nur die lesenden Verbindungen zu FHEM blockiert, Daten aus FHEM herausfinden funktioniert.

Das verstehe ich nicht. Ist das nicht dasselbe?
Gruß,
   Thorsten

[KölnSolar]

hängt wohl eher hiermit https://forum.fhem.de/index.php/topic,67543.15.html zusammen
Grüße Markus

[martin2day]

Hallo Thorsten,

du hast vollkommen Recht. Ich habe nur FHEMWEB auf verbose 5.
Bitte verzeiht diesen Fehler, ich verstehe einige Sachen einfach noch nicht so recht.
Ich habe das ganz noch einmal nachgestellt. Dieses mal mit verbose 5 global. Es werden wie erwartet noch mehr Daten aufgezeichnet.
Ich persönlich sehe hier nichts. Die Funktion Licht Sofa funktioniert aber auch weiterhin nicht. Ich habe den Schalter nur einmal betätigt.

Code Auswählen Erweitern

2017.02.21 19:00:04 4: WEB_192.168.10.151_62952 POST /fhem&fw_id=892&cmd=define+aaaan_Airport_Bad_OG+notify+Airport_Bad_OG+set+S7Radio_BadOG_ist_ein+%24EVENT; BUFLEN:0
2017.02.21 19:00:04 5: Cmd: >define aaaan_Airport_Bad_OG notify Airport_Bad_OG set S7Radio_BadOG_ist_ein $EVENT<
2017.02.21 19:00:04 5: Starting notify loop for aaaan_Airport_Bad_OG, 1 event(s), first is active
2017.02.21 19:00:04 5: End notify loop for aaaan_Airport_Bad_OG
2017.02.21 19:00:04 5: Starting notify loop for global, 1 event(s), first is DEFINED aaaan_Airport_Bad_OG
2017.02.21 19:00:04 5: createNotifyHash
2017.02.21 19:00:04 5: End notify loop for global
2017.02.21 19:00:04 4: WEB_192.168.10.151_62952 GET /fhem?detail=aaaan_Airport_Bad_OG&fw_id=892; BUFLEN:0
2017.02.21 19:00:04 5: Cmd: >get eventTypes list<
2017.02.21 19:00:04 4: name: /fhem?detail=aaaan_Airport_Bad_OG&fw_id=892 / RL:9845 / text/html; charset=UTF-8 / Content-Encoding: gzip
/
2017.02.21 19:00:04 4: WEB_192.168.10.151_62952 GET /fhem?cmd={ReadingsVal(%22aaaan_Airport_Bad_OG%22,%22ActionDetector%22,%22%22)}&XHR=1; BUFLEN:0
2017.02.21 19:00:04 5: Cmd: >{ReadingsVal("aaaan_Airport_Bad_OG","ActionDetector","")}<
2017.02.21 19:00:04 4: name: /fhem?cmd={ReadingsVal(%22aaaan_Airport_Bad_OG%22,%22ActionDetector%22,%22%22)}&XHR=1 / RL:21 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2017.02.21 19:00:04 4: WEB_192.168.10.151_62951 GET /fhem?cmd={ReadingsVal(%22aaaan_Airport_Bad_OG%22,%22active%22,%22%22)}&XHR=1; BUFLEN:0
2017.02.21 19:00:04 5: Cmd: >{ReadingsVal("aaaan_Airport_Bad_OG","active","")}<
2017.02.21 19:00:04 4: name: /fhem?cmd={ReadingsVal(%22aaaan_Airport_Bad_OG%22,%22active%22,%22%22)}&XHR=1 / RL:21 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2017.02.21 19:00:04 4: WEB_192.168.10.151_62953 GET /fhem?cmd={AttrVal(%22aaaan_Airport_Bad_OG%22,%22room%22,%22%22)}&XHR=1; BUFLEN:0
2017.02.21 19:00:04 5: Cmd: >{AttrVal("aaaan_Airport_Bad_OG","room","")}<
2017.02.21 19:00:04 4: name: /fhem?cmd={AttrVal(%22aaaan_Airport_Bad_OG%22,%22room%22,%22%22)}&XHR=1 / RL:21 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2017.02.21 19:00:04 4: WEB_192.168.10.151_62952 GET /fhem?XHR=1&inform=type=status;filter=aaaan_Airport_Bad_OG;since=1487700003;fmt=JSON&fw_id=892×tamp=1487700004551; BUFLEN:0
2017.02.21 19:00:06 4: WEB_192.168.10.151_62951 POST /fhem?cmd=save&XHR=1&fw_id=892; BUFLEN:0
2017.02.21 19:00:06 5: Cmd: >save<
2017.02.21 19:00:06 5: Starting notify loop for global, 1 event(s), first is SAVE
2017.02.21 19:00:06 5: createNotifyHash
2017.02.21 19:00:06 5: ZE.Activity: not on any display, ignoring notify
2017.02.21 19:00:06 5: ZE.Batterie: not on any display, ignoring notify
2017.02.21 19:00:06 5: battStatus: not on any display, ignoring notify
2017.02.21 19:00:06 5: End notify loop for global
2017.02.21 19:00:06 4: name: /fhem?cmd=save&XHR=1&fw_id=892 / RL:52 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/
2017.02.21 19:00:07 4: Connection closed for WEB_192.168.10.151_62952: EOF
2017.02.21 19:00:07 4: WEB_192.168.10.151_62951 GET /fhem?room=Beleuchtung; BUFLEN:0
2017.02.21 19:00:07 4: name: /fhem?room=Beleuchtung / RL:2996 / text/html; charset=UTF-8 / Content-Encoding: gzip
/
2017.02.21 19:00:08 4: WEB_192.168.10.151_62951 GET /fhem?XHR=1&inform=type=status;filter=room=Beleuchtung;since=1487700006;fmt=JSON&fw_id=893×tamp=1487700007899; BUFLEN:0
2017.02.21 19:00:08 5: HMUARTLGW HmUART read raw (24): fd001301bd050100277184104f923003381006010b005569
2017.02.21 19:00:08 5: HMUARTLGW HmUART read (23): fd001301bd050100277184104f923003381006010b005569 crc OK
2017.02.21 19:00:08 5: HMUARTLGW HmUART recv: 01 05 01 00 27 msg: 71 84 10 4F9230 033810 06010B00
2017.02.21 19:00:08 5: HMUARTLGW HmUART Dispatch: A0D7184104F923003381006010B00::-39:HmUART
2017.02.21 19:00:08 5: HmUART: dispatch A0D7184104F923003381006010B00::-39:HmUART
2017.02.21 19:00:10 4: WEB_192.168.10.151_62953 POST /fhem?cmd.Licht_Essen=set%20Licht_Essen%20off&room=Beleuchtung&room=Beleuchtung&XHR=1&fw_id=893; BUFLEN:0
2017.02.21 19:00:10 5: Cmd: >set Licht_Essen off<
2017.02.21 19:00:10 4: dummy set Licht_Essen off
2017.02.21 19:00:10 5: Starting notify loop for Licht_Essen, 1 event(s), first is off
2017.02.21 19:00:10 5: createNotifyHash
2017.02.21 19:00:10 5: ZE.Activity: not on any display, ignoring notify
2017.02.21 19:00:10 5: ZE.Batterie: not on any display, ignoring notify
2017.02.21 19:00:10 5: battStatus: not on any display, ignoring notify
2017.02.21 19:00:10 5: Triggering n_Licht_Essen
2017.02.21 19:00:10 4: n_Licht_Essen exec {
if ( (Value("S7Licht_Essen") eq "off" and Value("Licht_Essen") eq "on") or (Value("S7Licht_Essen") eq "on" and Value("Licht_Essen") eq "off") )
  { fhem ("set S7Licht_Essen_ein on") } else
  { fhem ("set S7Licht_Essen_ein off") }
}
2017.02.21 19:00:10 5: Cmd: >{
if ( (Value("S7Licht_Essen") eq "off" and Value("Licht_Essen") eq "on") or (Value("S7Licht_Essen") eq "on" and Value("Licht_Essen") eq "off") )
  { fhem ("set S7Licht_Essen_ein on") } else
  { fhem ("set S7Licht_Essen_ein off") }
}<
2017.02.21 19:00:10 5: Cmd: >set S7Licht_Essen_ein on<
2017.02.21 19:00:10 4: S7_DWrite_setABit on
2017.02.21 19:00:10 5: SPS S7_WriteBitToPLC: Write Bytes to PLC: 3, 802, 7 , 1, 1
2017.02.21 19:00:10 5: TCPClient WriteArea (IP= 192.168.10.100): 03, 00, 00, 24, 02, f0, 80, 32, 01, 00, 00, 31, 8a, 00, 0e, 00, 05, 05, 01, 12, 0a, 10, 01, 00, 01, 03, 22, 84, 00, 00, 07, 00, 03, 00, 01, 01
2017.02.21 19:00:10 5: TCPClient RecvISOPacket Expected Size = 22
2017.02.21 19:00:10 5: TCPClient RecvISOPacket (IP= 192.168.10.100): 32, 03, 00, 00, 31, 8a, 00, 02, 00, 01, 00, 00, 05, 01, ff
2017.02.21 19:00:10 5: Starting notify loop for S7Licht_Essen_ein, 1 event(s), first is on
2017.02.21 19:00:10 5: ZE.Activity: not on any display, ignoring notify
2017.02.21 19:00:10 5: ZE.Batterie: not on any display, ignoring notify
2017.02.21 19:00:10 5: battStatus: not on any display, ignoring notify
2017.02.21 19:00:10 5: End notify loop for S7Licht_Essen_ein
2017.02.21 19:00:10 5: End notify loop for Licht_Essen
2017.02.21 19:00:10 4: name: /fhem?cmd.Licht_Essen=set%20Licht_Essen%20off&room=Beleuchtung&room=Beleuchtung&XHR=1&fw_id=893 / RL:20 / text/plain; charset=UTF-8 / Content-Encoding: gzip
/

Auch habe ich mich verschrieben. Eingehende Verbindungen werden zeitweiße blockiert. Ausgehenden Verbindungen funktionieren.
Ich kann an die SPS bzw. an Homematic senden, die Befehle kommen auch an. Ich empfange aber keine Befehle von Homematic und der SPS.

Und wie gesagt nach ca. 2min nach dem definieren des notifys funktioniert alles ohne Probleme. Ich kann den Fehler aber mit jedem erneuten notify wieder hervorrufen.

Markus, ich verstehe nicht, was ich bei mir ändern muss.

Gruß Martin

[KölnSolar]

Hallo Martin,
Du musst $FW_CSRF an Deine Weblinks anhängen. Das ist neu und für mehr Sicherheit.
Du nutzt doch Weblinks ?
Grüße Markus

[martin2day]

Markus,

nein, nicht das ich wüsste. Zumindest nicht bei den beiden genannten Modulen.

Gruß Martin

[martin2day]

Guten Abend,

ich muss noch ein Update geben.
Durch einen anderen Beitrag bin ich auf die Idee gekommen und habe die fhem.pl aus dem Backup zurück gespielt.
Mit der alten Version habe ich leider auch dieses seltsame Verhalten.

Ich kann das nicht so recht verstehen warum immer nur nach einem define-notify für 2 Minuten nichts eingelesen wird.
Dannach arbeitet alles wie gewollt. Bei einem define-dummy passiert dies auch nicht.

Sehr eigenartig. Ich weiß gerade gar nicht wo ich nach dem Fehler suchen soll. Für das Programmieren und dann Testen ist das schon etwas nervig.

Gruß Martin

[KölnSolar]

vielleicht auch der neue perl syntax check https://forum.fhem.de/index.php/topic,67419.msg588645.html#msg588645 ?
Aber Sekunden 

[martin2day]

Guten Morgen,

Es hat ja den Anschein, dass es unmittelbar mit dem notify zusammenhängt.
Selbst wenn ich ein notify zw. Zwei Dummys erzeuge, hängt die Eingangsverbindung.
Was passiert denn genau wenn ich ein notify anlege?
Gibt es etwas was ich abstellen oder umstellen kann?

csrfToken attribut im WEB device habe ich bereits erfolglos versucht abzustellen.

Gruß Martin

[Thorsten Pferdekaemper]

Hi,
ich habe jetzt selbst mal ein update gemacht und mir die Notify-Definition genauer angeschaut. Ich kann da nichts böses sehen. In Deinem log sieht auch nichts nach Blockierung aus.
Also keine Ahnung...
Vielleicht solltest Du das mal in den Forenbereich verschieben, in dem notify behandelt wird. Möglicherweise kann sich dort jemand einen Reim darauf machen.
Gruß,
    Thorsten

[martin2day]

Hallo,

ich habe einen weiteren Test unternommen um das Problem einzugrenzen.
Ich habe auf meinem MAC noch eine FHEM Version mit der ich vor etwa einem Monat eingestiegen bin.
Diese habe ich kurzer Hand aktiviert und ein notify erstellt. Einlesen der Daten von der S7 funktioniert weiterhin.
Dann habe ich den kompletten Ordner fhem gesichert (Version geht) und ein update durchgeführt.
Nach dem Update habe ich die selben Verbindungsprobleme wie auf dem eigentlichen FHEM Server.

Allerdings fehlt mir jetzt wieder ein wenig das Wissen um hier vernünftig weiter anzusetzen. Die Idee von mir war Daten so lange zu ersetzen bis ich den Fehler eingegrenzt habe. Aber wie gesagt mir fehlt das Verständnis und ich habe schnell bemerkt dass ich hier zu einem gar nicht mehr gehenden System komme. Ich habe z.b. nur die ältere fhem.pl in das Verzeichnis kopiert. Da starte FHEM nicht mehr...

Ich bitte um Hilfe.

Gruß Martin

[martin2day]

Hallo zusammen,

durch probieren habe ich herausgefunden, dass die 91_notify.pm vom 24.01.2017 wunderbar funktioniert. Aller andere Dateien sind up to date.
Für mich ist das eine Lösung, aber wo das Problem genau liegt, kann ich leider nicht sagen.
Und da "nur" die S7_DRead blockiert werden gehe ich davon aus das es eventuell damit etwas zu tuen haben kann.

Gruß Martin

[Thorsten Pferdekaemper]

Hi,
kannst Du vielleicht mal die 91_notify.pm vom 24.1. hier dranhängen, sowei Deine aktuelle, die nicht funktioniert?
Dann können wir zumindest mal ein diff machen...
Gruß,
   Thorsten

[martin2day]

sehr gern...

[KölnSolar]

 lt. svn die einzige Änderung Zeile 59:

alt:   notifyRegexpChanged($hash, $re);
neu:  InternalTimer(0, sub(){  notifyRegexpChanged($hash, $re); }, $hash);

Edit: Und bis zu einer Reparatur/Lösung kannst Du per attr exclude_from_update im device global das notify-Modul ausschließen und trotzdem updates ausführen.