Hallo,
bei mir tritt folgendes Verhalten auf, was ich nicht verstehe (und bis jetzt auch unplausibel finde).
Ich habe ein Userreading u_RDG definiert, das auf ein Geräte-Reading d_RDG reagiert:
attr DEV userReadings u_RDG:d_RDG.* {...}
Userreading und Gerätereading sind als event-on-update-reading definiert.
Wenn ich manuell über
get DEV d_RDG
das Geräte-Reading auslese, wird wie erwartet das o.g. Userreading u_RDG getriggert und aktualisiert.
Ebenso wird das Userreading getriggert und aktualisiert, wenn das Geräte-Reading per "at" ausgelesen wird, z.B. stündlich:
define at_test at +*01:00:00 get DEV d_RDG
Wenn das Geräte-Reading allerdings per Notify ausgelesen wird, wird das Userreading u_RDG entgegen meiner Erwartung NICHT aktualisiert:
define notify_test notify DEV:u_RDG_2.* get DEV d_RDG
Es liegt übrigens nicht daran, dass das notify gar nicht ausgelöst wird. Im Logfile sehe ich das Auslösen des notifys und den Rückgabewert des get.
Kann mir jemand auf die Sprünge helfen, warum das "get" im Zusammenhang mit dem notify das Userreading nicht triggert? Oder wo liegt hier mein Denkfehler?
Keine Ahnung, ob es daran liegt, das das Notify vom selben Device ausgelöst worden ist wie dein get.
Versuche mal, das ganze mit einem sleep zu entkoppeln.
define notify_test notify DEV:u_RDG_2.* sleep 0.2;get DEV d_RDG
Wenn ein reading sich ändert, kann dadurch ja ein notify angestossen werden. Sollte das notify wiederum ein reading ändern, würde dies ja zu einer Endlosschleife führen, daher gibt es wohl diese Einschränkung.
Elekitrolurch
Danke für die Anregungen!
sleep habe ich probiert, bringt leider keine Änderung :(
Zur Idee mit der vermiedenen Endlosschleife...ist das irgendwo dokumentiert? Dann müsste ich gar nicht weiter nach möglichen Lösungen suchen.
Grundsätzlich könnte das zwar sein, fände ich persönlich aber unverständlich. Endlosschleifen bekommt man trotzdem hin, wenn man blöd programmiert. Das müsste man m.E. durch solche Einschränkungen nicht unbedingt verhindern, mein Usecase ist ja nicht so ungewöhnlich, denke ich?!
Oder denke ich zu quer und es gibt sinnvollere Umsetzungen für meine Idee?
Was ist u_RDG_2 ?
Zitat von: jhohmann am 29 Juni 2021, 10:58:36
define notify_test notify DEV:u_RDG_2.* sleep 0.2;get DEV d_RDG
Sowas in der Kommandozeile führt nicht zu einem notify mit einem sleep + ein Kommando, sondern definiert ein notify mit nur sleep.
Wäre es möglich ein "list DEV" und ein "list notify_test" zu sehen? Ein Blick im Eventmonitor könnte auch helfen.
Das u_RDG_2 ist ein beliebiges anderes Userreading des Device, das das notify auslöst.
Ich hatte das sleep auch mit "sleep 0.2;;" versehen, dann tauchte auch das folgende get mit auf.
Aber was soll ich sagen...gerade funktioniert es wie erwartet. Und das, obwohl ich dasselbe mache wie seit 2-3 Tagen... ::) ich weiß, kann nicht sein, es ist eine Maschine...aber ich habe grad keine Erklärung. In jedem Fall erstmal sorry für den wsl. unnötigen Aufwand. Wobei, jetzt funktioniert es ja, auch wenn ich nicht weiß warum.
Update...ich weiß nun warum es plötzlich ging und ein anderes Mal nicht.
Ist aber ein EXTREM merkwürdiges Verhalten, aber es ist reproduzierbar. Kann eigentlich nur ein Bug sein.
1) Definiere ich das notify wie folgt, funktioniert es:
define Compr notify Mythz:sGlobal:.* get Mythz sHeatDHWDay
2) Lasse ich den Namen des notifys mit "N" anfangen, funktioniert es nicht:
define NCompr notify Mythz:sGlobal:.* get Mythz sHeatDHWDay
Im ersten Fall wird
- das notify ausgelöst
- das reading sHeatDHWDay gelesen
- der get-Befehl im Event-Monitor angezeigt
- der Wert des readings sHeatDHWDay im Logfile protokolliert
Im zweiten Fall wird
- das notify ausgelöst
- das reading sHeatDHWDay gelesen
- der get-Befehl im Event-Monitor angezeigt
- der Wert des readings sHeatDHWDay im Logfile nicht protokolliert
Hört sich unglaubhaft an, aber es ist so...
Ich habe meine notifys alle umbenannt und kann damit leben. Aber gewollt ist sicher was anderes?!
Anmerkung: Hier wurde das auch mal thematisiert (aber nicht auf die Ursache zurückgeführt):
https://forum.fhem.de/index.php/topic,74347.0.html
ZitatIm ersten Fall wird
- das notify ausgelöst
- das reading sHeatDHWDay gelesen
- der Wert des readings sHeatDHWDay im Logfile protokolliert
Im zweiten Fall wird
- das notify ausgelöst
- das reading sHeatDHWDay gelesen
- der Wert des readings sHeatDHWDay im Logfile nicht protokolliert
Wenn in beiden Fällen das reading gelesen wird, funktioniert doch das notify und das get. Dann ist die Ursache eher in Mythz zu suchen.
Wieso Ursache in Mythz? Das Logfile hat mit dem Device doch gar nichts zutun?!
So ist es definiert:
define FileLog_HeatDHWDay FileLog /var/media/ftp/usb_data/log_signals/HeatDHWDay-%Y-KW%W.log Mythz:sHeatDHWDay.*
Zitat von: timtom2000 am 03 Juli 2021, 22:08:42
Wieso Ursache in Mythz? Das Logfile hat mit dem Device doch gar nichts zutun?!
Natürlich doch. Das Device generiert (oder nicht) die Events, die ggf in der Logfile landen.
Was siehst Du im EventMonitor?
Im Event-Monitor sieht in beiden Fällen alles identisch aus, da taucht das get immer zuverlässig auf (habe ich oben im Text grad mal ergänzt). Genau deswegen denke ich, dass es mit dem Device nichts zutun hat.
Kommt ein Event "Mythz sHeatDHWDay" in beiden Fällen oder nicht? Zeig bitte wie es aussieht wenn es geht und wenn es nicht geht
Gerne. Unten ein durchgehender Auszug aus Event-Monitor sowie Auszug aus Logfile.
Ich habe einmal ein notify "NCompr_Not_Ok" (17:56:31) und einmal ein notify "Compr_Ok" definiert (17:57:58).
Das triggernde sGlobal kommt zu 17:57:18 bzw. 17:59:15, sHeatDHWDay wird zeitgleich ausgelesen (sGlobal triggert noch weitere Readings).
Im Logfile taucht aber nur der Eintrag von 17:59:15 auf.
2021-07-04 17:56:31 notify NCompr_Not_Ok active
2021-07-04 17:56:31 Global global DEFINED NCompr_Not_Ok
2021-07-04 17:57:18 THZ Mythz sGlobal: outsideTemp: 20.3 flowTemp: 30.4 returnTemp: 31 hotGasTemp: 31.7 dhwTemp: 47.3 flowTempHC2: -60 evaporatorTemp: 31.2 condenserTemp: 27.4 mixerOpen: 0 mixerClosed: 0 heatPipeValve: 0 diverterValve: 0 dhwPump: 0 heatingCircuitPump: 0 solarPump: 0 compressor: 0 boosterStage3: 0 boosterStage2: 0 boosterStage1: 0 highPressureSensor: 0 lowPressureSensor: 0 evaporatorIceMonitor: 0 signalAnode: 0 evuRelease: 1 ovenFireplace: 1 STB: 0 outputVentilatorPower: 0 inputVentilatorPower: 0 mainVentilatorPower: 0 outputVentilatorSpeed: 0 inputVentilatorSpeed: 0 mainVentilatorSpeed: 0 outside_tempFiltered: 21.7 relHumidity: 0 dewPoint: 0 P_Nd: 10.76 P_Hd: 11.01 actualPower_Qc: 0.000 actualPower_Pel: 0.000 collectorTemp: -60 insideTemp: 25.6 windowOpen: 0 quickAirVent: 0 flowRate: 0 p_HCw: 1.66 humidityAirOut: 41.27
2021-07-04 17:57:18 THZ Mythz uOutsideTemp: 20.3
2021-07-04 17:57:18 THZ Mythz uFlowTemp: 30.4
2021-07-04 17:57:18 THZ Mythz uDHWTemp: 47.3
2021-07-04 17:57:18 THZ Mythz uAussenTFilt: 21.7
2021-07-04 17:57:18 THZ Mythz uHumidityAirOut: 41.27
2021-07-04 17:57:18 THZ Mythz uSpreizung: -0.600000000000001
2021-07-04 17:57:18 THZ Mythz sHeatDHWDay: 7458 Wh
2021-07-04 17:57:44 Global global DELETED NCompr_Not_Ok
2021-07-04 17:57:58 notify Compr_Ok active
2021-07-04 17:57:58 Global global DEFINED Compr_Ok
2021-07-04 17:58:09 THZ Mythz sHC1: outsideTemp: 20.3 x08: 0 returnTemp: 31 integralHeat: 0 flowTemp: 30.4 heatSetTemp: 8 heatTemp: 30.8 seasonMode: summer integralSwitch: 200 hcOpMode: setback roomSetTemp: 15 x60: 0 x64: 0 insideTempRC: 21.5 x72: 0 x76: 0 onHysteresisNo: 0 offHysteresisNo: 0 hcBoosterStage: 0
2021-07-04 17:58:09 THZ Mythz uInsideTemp: 21.5
2021-07-04 17:59:15 THZ Mythz sGlobal: outsideTemp: 20.3 flowTemp: 30.5 returnTemp: 31.1 hotGasTemp: 31.6 dhwTemp: 47.3 flowTempHC2: -60 evaporatorTemp: 31.2 condenserTemp: 27.4 mixerOpen: 0 mixerClosed: 0 heatPipeValve: 0 diverterValve: 0 dhwPump: 0 heatingCircuitPump: 0 solarPump: 0 compressor: 0 boosterStage3: 0 boosterStage2: 0 boosterStage1: 0 highPressureSensor: 0 lowPressureSensor: 0 evaporatorIceMonitor: 0 signalAnode: 0 evuRelease: 1 ovenFireplace: 1 STB: 0 outputVentilatorPower: 0 inputVentilatorPower: 0 mainVentilatorPower: 0 outputVentilatorSpeed: 0 inputVentilatorSpeed: 0 mainVentilatorSpeed: 0 outside_tempFiltered: 21.7 relHumidity: 0 dewPoint: 0 P_Nd: 10.81 P_Hd: 11.01 actualPower_Qc: 0.000 actualPower_Pel: 0.000 collectorTemp: -60 insideTemp: 25.5 windowOpen: 0 quickAirVent: 0 flowRate: 0 p_HCw: 1.66 humidityAirOut: 40.95
2021-07-04 17:59:15 THZ Mythz uFlowTemp: 30.5
2021-07-04 17:59:15 THZ Mythz uReturnTemp: 31.1
2021-07-04 17:59:15 THZ Mythz uHumidityAirOut: 40.95
2021-07-04 17:59:15 THZ Mythz sHeatDHWDay: 7458 Wh
2021-07-04 17:59:29 THZ Mythz sDHW: dhwTemp: 47.3 outsideTemp: 20.2 dhwSetTemp: 41 compBlockTime: 0 out: 0000 heatBlockTime: 1123 dhwBoosterStage: 0 pasteurisationMode: 0 dhwOpMode: normal x36: 3C4C
2021-07-04 17:59:31 at at_Handbetrieb Next: 18:04:30
2021-07-04 17:59:39 Global global DELETED Compr_Ok
2021-07-04_09:30:14 sHeatDHWDay: 3776 Wh
2021-07-04_14:18:11 sHeatDHWDay: 3777 Wh
2021-07-04_14:53:14 sHeatDHWDay: 7458 Wh
2021-07-04_17:59:14 sHeatDHWDay: 7458 Wh
Hmm. In der Tat merkwürdig.
Hättest Du bitte ein komplettes "list" vom FileLog Device?
Ja, wenn ich das nicht selber sehen würde, würde ich es auch nicht glauben...unten das list.
Hast du dir mal den Spaß gemacht und solche zwei notifys + logfile definiert? Der Trigger kann irgendwas sein, ebenso das per get ausgelesene reading. Wäre mal interessant, ob du das nachstellen kannst...
Internals:
DEF /var/media/ftp/usb_data/log_signals/HeatDHWDay-%Y-KW%W.log Mythz:sHeatDHWDay.*
FD 34
FUUID 60d4f670-f33f-a459-4002-3c2df15cdfcfa936
NAME FileLog_HeatDHWDay
NOTIFYDEV Mythz
NR 136
NTFY_ORDER 50-FileLog_HeatDHWDay
REGEXP Mythz:sHeatDHWDay.*
STATE active
TYPE FileLog
currentlogfile /var/media/ftp/usb_data/log_signals/HeatDHWDay-2021-KW26.log
logfile /var/media/ftp/usb_data/log_signals/HeatDHWDay-%Y-KW%W.log
READINGS:
2021-07-04 17:59:14 linesInTheFile 79
Attributes:
archivedir /var/media/ftp/usb_data/log_signals/archive/
nrarchive 2
outputFormat "$TIMESTAMP $EVENT\n"
Ich mach mal später in der Nacht einen Test mit dummies und melde mich.
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
setreading Mythz sGlobal test2mache, wird sHeatDHWDay mutig in der FileLog protokolliert.
Hast Du schon in der fhem-Log mit verbose 5 geguckt?
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...
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
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
setreading DummyDev DummyTrigger test2
Hier das Logfile mit verbose 5
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<
Und wenn Du das notify umbenennst, funktioniert es wieder?
Kannst Du auch das Ergebnis von "version" posten?
Ja, wenn ich es umbenenne funktioniert es wieder, verrückt.
Gerade nochmal klinisch rein hintereinander getestet mit genau diesem Ablauf:
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.
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:
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:
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.
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.
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!