Userreading wird aus Notify nicht ausgelöst

amenomade · 04 Juli 2021, 20:10:20

Ich mach mal später in der Nacht einen Test mit dummies und melde mich.

amenomade · 04 Juli 2021, 21:38:54

Also... ich kann das mit dummies zumindest nicht reproduzieren:

define Mythz dummy

define logMythz FileLog %L/mythz.log Mythz:sHeatDHWDay.*

define NCompr_Not_Ok notify Mythz:sGlobal.* setreading Mythz sHeatDHWDay 7458 Wh

Jedes mal wenn ich ein

Code Auswählen

setreading Mythz sGlobal test2mache, wird sHeatDHWDay mutig in der FileLog protokolliert.

Hast Du schon in der fhem-Log mit verbose 5 geguckt?

timtom2000 · 04 Juli 2021, 22:59:07

Danke fürs Testen! Dein Beispiel funktioniert bei mir aber auch zuverlässig, sowas blödes...
Ich mache morgen mal ein verbose 5. Die Ausgaben verstehe ich aber nicht wirklich, so weit reicht es dann bei mir leider nicht...

timtom2000 · 04 Juli 2021, 23:15:27

Kommando zurück, hab beim Übernehmen einen Fehler gemacht, weil ich die Variablen ändern musste, damit mein "echtes Gerät" nicht durcheinander kommt.
Auch dein Beispiel funktioniert nicht.

Ich habe es wie folgt abstrahiert

Code Auswählen

defmod DummyDev dummy

defmod FileLogDummy FileLog /var/media/ftp/usb_prog/dummylog.log DummyDev:DummyReading.*

defmod NCompr_Not_Ok notify DummyDev:DummyTrigger.* setreading DummyDev DummyReading 7458 Wh

Und so getriggert

Code Auswählen

setreading DummyDev DummyTrigger test2

Hier das Logfile mit verbose 5

Code Auswählen

2021.07.04 23:08:41 5: Starting notify loop for global, 1 event(s), first is ATTR global verbose 5
2021.07.04 23:08:41 5: End notify loop for global
2021.07.04 23:08:41 4: WEB: /fhem?cmd=attr%20global%20verbose%205&XHR=1&fwcsrf=csrf_674554963456321&fw_id=511 / RL:20 / text/plain; charset=UTF-8 / Content-Encoding: gzip
 / Cache-Control: no-cache, no-store, must-revalidate

2021.07.04 23:08:41 5: POST /fhem?cmd=defmod%20DummyDev%20dummy&XHR=1&fwcsrf=csrf_674554963456321&fw_id=511 HTTP/1.1
Host: 192.168.188.20:8083
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:88.0) Gecko/20100101 Firefox/88.0
Accept: text/plain, */*; q=0.01
Accept-Language: de,en-US;q=0.7,en;q=0.3
Accept-Encoding: gzip, deflate
cache-control: no-cache
X-Requested-With: XMLHttpRequest
Origin: http://192.168.188.20:8083
DNT: 1
Connection: keep-alive
Referer: http://192.168.188.20:8083/fhem/dashboard/MyDashboard
Content-Length: 0
2021.07.04 23:08:42 4: WEB_192.168.188.54_65475 POST /fhem?cmd=defmod%20DummyDev%20dummy&XHR=1&fwcsrf=csrf_674554963456321&fw_id=511; BUFLEN:0
2021.07.04 23:08:42 5: Cmd: >defmod DummyDev dummy<
2021.07.04 23:08:42 5: Starting notify loop for global, 1 event(s), first is MODIFIED DummyDev
2021.07.04 23:08:42 5: End notify loop for global
2021.07.04 23:08:42 4: WEB: /fhem?cmd=defmod%20DummyDev%20dummy&XHR=1&fwcsrf=csrf_674554963456321&fw_id=511 / RL:20 / text/plain; charset=UTF-8 / Content-Encoding: gzip
 / Cache-Control: no-cache, no-store, must-revalidate

2021.07.04 23:08:42 5: POST /fhem?cmd=defmod%20FileLogDummy%20FileLog%20%2Fvar%2Fmedia%2Fftp%2Fusb_prog%2Fdummylog.log%20DummyDev%3ADummyReading.*&XHR=1&fwcsrf=csrf_674554963456321&fw_id=511 HTTP/1.1
Host: 192.168.188.20:8083
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:88.0) Gecko/20100101 Firefox/88.0
Accept: text/plain, */*; q=0.01
Accept-Language: de,en-US;q=0.7,en;q=0.3
Accept-Encoding: gzip, deflate
cache-control: no-cache
X-Requested-With: XMLHttpRequest
Origin: http://192.168.188.20:8083
DNT: 1
Connection: keep-alive
Referer: http://192.168.188.20:8083/fhem/dashboard/MyDashboard
Content-Length: 0
2021.07.04 23:08:42 4: WEB_192.168.188.54_65475 POST /fhem?cmd=defmod%20FileLogDummy%20FileLog%20%2Fvar%2Fmedia%2Fftp%2Fusb_prog%2Fdummylog.log%20DummyDev%3ADummyReading.*&XHR=1&fwcsrf=csrf_674554963456321&fw_id=511; BUFLEN:0
2021.07.04 23:08:42 5: Cmd: >defmod FileLogDummy FileLog /var/media/ftp/usb_prog/dummylog.log DummyDev:DummyReading.*<
2021.07.04 23:08:42 5: Starting notify loop for global, 1 event(s), first is MODIFIED FileLogDummy
2021.07.04 23:08:42 5: createNotifyHash
2021.07.04 23:08:42 5: End notify loop for global
2021.07.04 23:08:42 4: WEB: /fhem?cmd=defmod%20FileLogDummy%20FileLog%20%2Fvar%2Fmedia%2Fftp%2Fusb_prog%2Fdummylog.log%20DummyDev%3ADummyReading.*&XHR=1&fwcsrf=csrf_674554963456321&fw_id=511 / RL:20 / text/plain; charset=UTF-8 / Content-Encoding: gzip
 / Cache-Control: no-cache, no-store, must-revalidate

2021.07.04 23:08:42 5: POST /fhem?cmd=defmod%20NCompr_Not_Ok%20notify%20DummyDev%3ADummyTrigger.*%20setreading%20DummyDev%20DummyReading%207458%20Wh&XHR=1&fwcsrf=csrf_674554963456321&fw_id=511 HTTP/1.1
Host: 192.168.188.20:8083
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:88.0) Gecko/20100101 Firefox/88.0
Accept: text/plain, */*; q=0.01
Accept-Language: de,en-US;q=0.7,en;q=0.3
Accept-Encoding: gzip, deflate
cache-control: no-cache
X-Requested-With: XMLHttpRequest
Origin: http://192.168.188.20:8083
DNT: 1
Connection: keep-alive
Referer: http://192.168.188.20:8083/fhem/dashboard/MyDashboard
Content-Length: 0
2021.07.04 23:08:42 4: WEB_192.168.188.54_65475 POST /fhem?cmd=defmod%20NCompr_Not_Ok%20notify%20DummyDev%3ADummyTrigger.*%20setreading%20DummyDev%20DummyReading%207458%20Wh&XHR=1&fwcsrf=csrf_674554963456321&fw_id=511; BUFLEN:0
2021.07.04 23:08:42 5: Cmd: >defmod NCompr_Not_Ok notify DummyDev:DummyTrigger.* setreading DummyDev DummyReading 7458 Wh<
2021.07.04 23:08:42 5: Starting notify loop for NCompr_Not_Ok, 1 event(s), first is active
2021.07.04 23:08:42 5: createNotifyHash
2021.07.04 23:08:43 5: End notify loop for NCompr_Not_Ok
2021.07.04 23:08:43 5: Starting notify loop for global, 1 event(s), first is MODIFIED NCompr_Not_Ok
2021.07.04 23:08:43 5: End notify loop for global
2021.07.04 23:08:43 4: WEB: /fhem?cmd=defmod%20NCompr_Not_Ok%20notify%20DummyDev%3ADummyTrigger.*%20setreading%20DummyDev%20DummyReading%207458%20Wh&XHR=1&fwcsrf=csrf_674554963456321&fw_id=511 / RL:20 / text/plain; charset=UTF-8 / Content-Encoding: gzip
 / Cache-Control: no-cache, no-store, must-revalidate

2021.07.04 23:08:47 5: POST /fhem?cmd=setreading%20DummyDev%20DummyTrigger%20test2&XHR=1&fwcsrf=csrf_674554963456321&fw_id=540 HTTP/1.1
Host: 192.168.188.20:8083
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:88.0) Gecko/20100101 Firefox/88.0
Accept: text/plain, */*; q=0.01
Accept-Language: de,en-US;q=0.7,en;q=0.3
Accept-Encoding: gzip, deflate
cache-control: no-cache
X-Requested-With: XMLHttpRequest
Origin: http://192.168.188.20:8083
DNT: 1
Connection: keep-alive
Referer: http://192.168.188.20:8083/fhem/dashboard/MyDashboard
Content-Length: 0
2021.07.04 23:08:47 4: WEB_192.168.188.54_65475 POST /fhem?cmd=setreading%20DummyDev%20DummyTrigger%20test2&XHR=1&fwcsrf=csrf_674554963456321&fw_id=540; BUFLEN:0
2021.07.04 23:08:47 5: Cmd: >setreading DummyDev DummyTrigger test2<
2021.07.04 23:08:47 5: Starting notify loop for DummyDev, 1 event(s), first is DummyTrigger: test2
2021.07.04 23:08:47 5: createNotifyHash
2021.07.04 23:08:47 5: Triggering NCompr_Not_Ok
2021.07.04 23:08:47 4: NCompr_Not_Ok exec setreading DummyDev DummyReading 7458 Wh
2021.07.04 23:08:47 5: Cmd: >setreading DummyDev DummyReading 7458 Wh<
2021.07.04 23:08:47 5: End notify loop for DummyDev
2021.07.04 23:08:47 4: WEB: /fhem?cmd=setreading%20DummyDev%20DummyTrigger%20test2&XHR=1&fwcsrf=csrf_674554963456321&fw_id=540 / RL:20 / text/plain; charset=UTF-8 / Content-Encoding: gzip
 / Cache-Control: no-cache, no-store, must-revalidate

2021.07.04 23:08:47 5: THZ_Get: Try to get 'sFan'
2021.07.04 23:08:47 5: THZ_Get_Comunication: Check if port is open. State = '(opened)'
2021.07.04 23:08:47 5: Mythz sending 02
2021.07.04 23:08:47 5: SW: 02
2021.07.04 23:08:47 5: Mythz start Function THZ_ReadAnswer
2021.07.04 23:08:47 5: THZ_ReadAnswer: uc unpack: '10'
2021.07.04 23:08:47 5: Mythz sending 0100E9E81003
2021.07.04 23:08:47 5: SW: 0100E9E81003
2021.07.04 23:08:47 5: Mythz start Function THZ_ReadAnswer
2021.07.04 23:08:47 5: THZ_ReadAnswer: uc unpack: '1002'
2021.07.04 23:08:47 5: Mythz sending 10
2021.07.04 23:08:47 5: SW: 10
2021.07.04 23:08:48 5: Mythz start Function THZ_ReadAnswer
2021.07.04 23:08:48 5: THZ_ReadAnswer: uc unpack: '01006BE80000000000000000000000000000000000000000000000000000002E32006E006E2323001003'
2021.07.04 23:08:48 5: Mythz sending 10
2021.07.04 23:08:48 5: SW: 10
2021.07.04 23:08:48 5: Parse message: 6BE80000000000000000000000000000000000000000000000000000002E32006E006E232300
2021.07.04 23:08:48 5: Message length: 76
2021.07.04 23:09:01 4: Connection closed for WEB_192.168.188.54_65447: EOF
2021.07.04 23:09:01 5: POST /fhem HTTP/1.1
Host: 192.168.188.20:8083
User-Agent: Mozilla/5.0 (Windows NT 10.0; Win64; x64; rv:88.0) Gecko/20100101 Firefox/88.0
Accept: text/html,application/xhtml+xml,application/xml;q=0.9,image/webp,*/*;q=0.8
Accept-Language: de,en-US;q=0.7,en;q=0.3
Accept-Encoding: gzip, deflate
Content-Type: application/x-www-form-urlencoded
Content-Length: 72
Origin: http://192.168.188.20:8083
DNT: 1
Connection: keep-alive
Referer: http://192.168.188.20:8083/fhem?room=all
Upgrade-Insecure-Requests: 1
2021.07.04 23:09:01 4: WEB_192.168.188.54_65475 POST /fhem&fw_id=557&room=all&fwcsrf=csrf_674554963456321&cmd=attr+global+verbose+2; BUFLEN:0
2021.07.04 23:09:01 5: Cmd: >attr global verbose 2<

amenomade · 05 Juli 2021, 01:17:46

Und wenn Du das notify umbenennst, funktioniert es wieder?

Kannst Du auch das Ergebnis von "version" posten?

timtom2000 · 05 Juli 2021, 21:10:32

Ja, wenn ich es umbenenne funktioniert es wieder, verrückt.

Gerade nochmal klinisch rein hintereinander getestet mit genau diesem Ablauf:

Code Auswählen

attr global verbose 5
defmod DummyDev dummy
defmod FileLogDummy FileLog /var/media/ftp/usb_prog/dummylog.log DummyDev:DummyReading.*
defmod NCompr_Not_Ok notify DummyDev:DummyTrigger.* setreading DummyDev DummyReading 7458 Wh
setreading DummyDev DummyTrigger test2
attr global verbose 2

Einmal natürlich mit "Compr_Ok", aber ansonsten völlig identisch. Dazwischen die vormaligen defines mit delete gelöscht, genau so wie das Logfile. Einmal wird geloggt, einmal nicht.
Im Anhang die beiden Logfiles dazu (mit verbose 5) und auch mal das Ergebnis von version. Ich bin aber eigentlich einigermaßen up-to-date, denke ich.

rudolfkoenig · 06 Juli 2021, 10:04:54

ZitatEinmal wird geloggt, einmal nicht.

Setreading erzeugt ein Event, Notify ein Zweites, fuer das gleiche Geraet, in der gleichen "Event-Abarbeitungs-Kette".
Events fuer das gleiche Geraet aus der "eigenen" Event-Kette zu erzeugen ist was Spezielles, und wird davon abgeraten, da FHEM die Moeglichkeit der Rekursion in einer Event-Kette unterbindet, und man deswegen auf Feinheiten (s.u.) achten muss.

Die Kette wird in der NTFY_ORDER Reihenfolge abgearbeitet, was (unter anderem) aus dem Namen gebildet wird:

Code Auswählen

fhem> l .* NTFY_ORDER
FileLogDummy             50-FileLogDummy
NCompr_Not_Ok            50-NCompr_Not_Ok

Wenn FileLogs NTFY_ORDER vor der Notifys kommt, dann gibt es noch kein Event zum Loggen, sonst schon.

Die Loesung ist (wie schon vorgeschlagen), im notify das Event in einer neuen Event-Kette, mit sleep zu starten:

Code Auswählen

defmod NCompr_Not_Ok notify DummyDev:DummyTrigger.* sleep 0.001;; setreading DummyDev DummyReading 7458 Wh

Nachtrag: diese Besonderheit ist auch der eigentliche Grund, warum UserReadings eingefuehrt wurden: diese werden vor der Abarbeitung der Event-Kette berechnet/gesetzt.

amenomade · 06 Juli 2021, 12:10:45

Hehe

Das hat sich gelohnt, dass ich dich auf dem Thema gebracht habe ! Vielen Dank Rudi für die ausführliche Erklärung. Das ist wirklich tricky. Die Vermutung von jhohmann war dann schon richtig. Da habe ich selbst auch viel gelernt.

timtom2000 · 06 Juli 2021, 20:51:39

Ach, die Reihenfolge der Abarbeitung hängt vom Namen ab...da muss Otto-Normal-User mal drauf kommen

im Falle dieses FileLog's hätte also jedes notify von A-Fi wie erwartet geklappt, von Fj-Z nicht (oder man lässt das FileLog mit z anfangen, dann ist man auf der relativ sicheren Seite; genau das werde ich jetzt mal tun, sicher ist sicher). Daran hätte ich nie gedacht, eher dass im Sinne fifo, ganz simpel, die Reihenfolge der Abarbeitung von der Reihenfolge des Auftretens abhängt. Aber das geht wsl. aus anderen Gründen nicht, da stecke ich zugegebenermaßen viel zu wenig drin!

Vielen Dank nochmal für die Erklärung! Ich habe ja bis zum Schluss befürchtet, dass ich selber irgendeinen Mist gebaut habe...zum Glück nicht, wenn man mal davon absieht, dass ich ein Konstrukt gewählt habe, wovon abgeraten wird, was aber total praktisch ist in dem Fall (und den Code vereinfacht).

P.S. Besonderen Dank an amenomade für dein Durchhaltevermögen, super!