[gelöst] FileLog: Attribut filelog-event-min-interval funktioniert nicht wie erw

[RalfRog]

Ich die Frage mal hier gepostet (mir wäre nur noch Sonstiges eingefallen)

Ich hatte bisher nicht groß geprüft ob es funktioniert. Lt. Beschreibung in der Commandref:

filelog-event-min-interval
Dieses Attribut enthält eine durch Kommata getrennte Liste von "devspec:readings:minInterval" Tripel. readings kann ein regexp sein. Die Daten werden nur dann geschrieben, falls seit dem letzten Auftreten des gleichen Events mindestens minInterval Sekunden vergangen sind.

hatte ich erwartet, dass die definierten Werte max. stündlich im Log landen. Bei mir passiert das aber häufiger ggfs. auch alle 5 Minuten. Es scheint als würde das Attribut nicht beachtet.
--> Attribut: filelog-event-min-interval MQTT2_ESP_2:Wifi.*:3600,MQTT2_ESP_2:Heap.*:3600,MQTT2_ESP_2:Load.*:3600

Code Auswählen Erweitern


2022-08-09_15:44:53 MQTT2_ESP_2 Wifi_Signal: -74
2022-08-09_15:44:53 MQTT2_ESP_2 Wifi_RSSI: 52
2022-08-09_15:49:53 MQTT2_ESP_2 Wifi_Signal: -76
2022-08-09_15:49:53 MQTT2_ESP_2 Wifi_RSSI: 48
2022-08-09_15:54:53 MQTT2_ESP_2 Wifi_Signal: -74
2022-08-09_15:54:53 MQTT2_ESP_2 Wifi_RSSI: 52


List vom FileLog

Code Auswählen Erweitern


Internals:
   DEF        ./log/MQTT2_ESP_2-%Y.log MQTT2_ESP_2
   FD         37
   FUUID      62aa562d-f33f-a8ec-d182-7ba34de906667a92
   NAME       FileLog_MQTT2_ESP_2
   NOTIFYDEV  MQTT2_ESP_2
   NR         515
   NTFY_ORDER 50-FileLog_MQTT2_ESP_2
   REGEXP     MQTT2_ESP_2
   STATE      active
   TYPE       FileLog
   currentlogfile ./log/MQTT2_ESP_2-2022.log
   logfile    ./log/MQTT2_ESP_2-%Y.log
   READINGS:
     2022-08-09 16:24:53   linesInTheFile  9651
Attributes:
   alias      FileLog_Zaehler_ESP-2
   filelog-event-min-interval MQTT2_ESP_2:Wifi.*:3600,MQTT2_ESP_2:Heap.*:3600,MQTT2_ESP_2:Load.*:3600
   ignoreRegexp MQTT2_ESP_2:Up.*|MQTT2_ESP_2:Time:.*|MQTT2_ESP_2:MT691_energy.*|MQTT2_ESP_2:MT691_power.*
   logtype    text
   room       Logs,MQTT


Randinfo: das dahinter liegende Device enthält ein "event-on-change-reading  .*" und das MQTT-Gerät sende alle 300 Sekunden.

[Beta-User]

Das Problem mit solchen numerischen Readings ist eigentlich immer dasselbe, wenn man keine Hysterese setzt: kleine Abweichung => Event => Auswertung/Log....

Anders gesagt: .*-min-interval greift erst, wenn tatsächlich _kein anderes/geändertes_ Event (auf dem betr. Readings, das per "readings" spezifiziert ist) eintritt. Aber Wechsel von -74 zu -76 ist halt _was anderes_. Würde daher das "einfache" .* im Ausgangsdevice überdenken und da halt für diese Readings eine Hysterese definieren (ca. 5?).

[betateilchen]

Ich die Frage mal hier gepostet (mir wäre nur noch Sonstiges eingefallen)

"Sonstiges" wäre genau so falsch gewesen wie hier in den Anfängerfragen.

Code Auswählen Erweitern

help filelog

liefert als Information:

Module: 92_FileLog.pm Maintainer: rudolfkoenig Forum: Automatisierung

Man muss sich also gar nix "einfallen" lassen, man kann einfach abfragen, wo ein Thread korrekt hingehört. Siehe auch https://forum.fhem.de/index.php/topic,13092.0.html

[RalfRog]

"Sonstiges" wäre genau so falsch gewesen wie hier in den Anfängerfragen.

Code Auswählen Erweitern

help filelog

Jo 
Richtig gucken heisst die Devise

[RalfRog]

Das Problem mit solchen numerischen Readings ist eigentlich immer dasselbe, wenn man keine Hysterese setzt: kleine Abweichung => Event => Auswertung/Log....

Anders gesagt: .*-min-interval greift erst, wenn tatsächlich _kein anderes/geändertes_ Event (auf dem betr. Readings, das per "readings" spezifiziert ist) eintritt. Aber Wechsel von -74 zu -76 ist halt _was anderes_. Würde daher das "einfache" .* im Ausgangsdevice überdenken und da halt für diese Readings eine Hysterese definieren (ca. 5?).

Da hast du sicher recht...

Trotz allem wäre im FileLog (hier das spezielle Attribut im FileLog ) meine Erwartung gewesen, dass das Attribut "filelog-event-min-interval MQTT2_ESP_2:Wifi.*:3600" einen Logeintrag maximal alle Stunde zulässt - egal wie die Definition der events im Device aussieht.
Mit dem von dir beschriebenen Problem zusammen würde ich eher schlussfolgern, dass weniger Events geloggt werden.

Gruß Ralf

[frank]

"min" bedeuted hier nicht wirklich minimum, eher mindestens.

[RalfRog]

"min" bedeuted hier nicht wirklich minimum, eher mindestens.

Commandref:

Code Auswählen Erweitern


.... Die Daten werden nur dann geschrieben, falls seit dem letzten Auftreten des gleichen Events mindestens minInterval Sekunden vergangen sind.


Hallo Frank
Ja genau mindestens 3600 Sekunden müssen vergangen sein bevor das Event wieder in das Log geschrieben werden.
Und nicht nur 300 (oder ähnlich).

Gruß Ralf

[Beta-User]

[gelöst]?

Nach meiner Auffassung ist die commandref eindeutig:

falls seit dem letzten Auftreten des gleichen Events

Wenn du Readings loggst, besteht das Event eben (wie sonst auch üblich) nicht nur aus dem Reading-Namen, sondern auch aus dem Wert.

Anders gesagt: Man kann mit diesem Attribut lediglich das Intervall verlängern, das sich durch event-min-interval direkt am Device ergibt. Nicht mehr, nicht weniger.
Und (vorgelagert) mit der Hysterese am Device (per event-on-change-reading) bestimmst du eben, was überhaupt erst eine "Änderung" sein soll.

[OdfFhem]

Mit dem von dir beschriebenen Problem zusammen würde ich eher schlussfolgern, dass weniger Events geloggt werden.

Neben event-on-change-reading gibt es beim Event auslösenden Device ein Attribut namens event-min-interval und dient zu folgendem Zweck:

... damit nach Ablauf der Mindestzeit ein Event auch ohne Wertänderung nicht mehr unterdrückt wird.

filelog-event-min-interval und event-min-interval verhalten sich damit quasi identisch.

In Verbindung mit den (auch utopisch hohen) Schwellwerten, die in event-on-change-reading festgelegt werden können, kann man problemlos erreichen, dass maximal 1 Event pro Stunde ausgelöst wird ...

Sollten die unterdrückten Events an anderer Stelle fehlen, dann hilft diese Vorgehensweise natürlich nicht.

[RalfRog]

Hallo Zusammen
Danke bis hierhin.
Ich habe gestern nachmittag das Attribut mal verändert. Einfach um zu sehen ob es irgendein Problem mit der Schreibweise oder ähnlichem gibt:
aus   --> filelog-event-min-interval MQTT2_ESP_2:Wifi.*:3600,MQTT2_ESP_2:Heap.*:3600,MQTT2_ESP_2:Load.*:3600
jetzt --> filelog-event-min-interval MQTT2_ESP_2:Wifi.*:1800 (bewusst kürzer gewählt)

Ich muss das Log noch genau genau durchsehen. Es scheint aber, dass nun tatsächlich nicht öfter als 30 Minuten ein Eintrag für "Wifi_Signal: -75" kommt.
Ich werde mal schrittweise in die alte Schreibweise (mehrfache readings) gehen und schauen ob und wenn ja der alte Effekt wieder eintritt.
(sonst schmeiss ich Heap und Load einfach weg, ist sowieso nur mäßig interessant)

Nach meiner Auffassung ist die commandref eindeutig:Wenn du Readings loggst, besteht das Event eben (wie sonst auch üblich) nicht nur aus dem Reading-Namen, sondern auch aus dem Wert.

Ok, wenn das so zu sehen ist (und nicht nur auf den Namen des Reading wirkt), dann ist das Verhalten erwartbar.
Dann liegt ein Missverständnis (der nicht programmienden Zunft) in der Interpretation vor. Reading = Name und Wert 

[Beta-User]

Es scheint aber, dass nun tatsächlich nicht öfter als 30 Minuten ein Eintrag für "Wifi_Signal: -75" kommt.

Dann ist das Zufall, und der Wert hat sich schlicht nicht verändert....

Reading = Name und Wert 

Nope! Event = Reading-Name+Wert!

Wobei "=" auch missverständlich ist, es müßte heißen: "setzt sich zusammen aus"

[frank]

Ja genau mindestens 3600 Sekunden müssen vergangen sein bevor das Event wieder in das Log geschrieben werden.
Und nicht nur 300 (oder ähnlich).

nein, es kommt mindestens 1 event pro stunde. also ggf auch mehr.

aber:
events werden nur generiert, wenn neue "messwerte" eintreffen.
wenn zb die messwerte alle 45 min eintreffen, gäbe es mit "min-interval=3600" ggf nur alle 90 min ein neues event. 

[RalfRog]

Hallo Zusammen
Nochmal vielen Dank für die Hinweise - auf jeden Fall was gelernt.

• insbesondere wie sich ein Event zusammensetzt  --> Event = Reading-Name+Wert! (@Frank)
• Erinnerung an das Thema Schwellwerte

Ganz wertfrei hier meine Beobachtung (Hinweis @Beta-User: Zufall --> hab ich im Kopf):

• am 9.8 nachmittags habe ich im FileLog das Attribut reduziert auf --> "filelog-event-min-interval  MQTT2_ESP_2:Wifi.*:1800"
  > alle Einträge "MQTT2_ESP_2 Wifi_Signal" bis zum 10.8 haben mindestens 30 Minuten Abstand (kann Zufall sein)
  
  
• am 10.8 nachmittags habe ich im FileLog das Attribut erweitert auf --> "filelog-event-min-interval  MQTT2_ESP_2:Wifi.*:1800,MQTT2_ESP_2:Load.*:1800"
  > alle Einträge "MQTT2_ESP_2 Wifi_Signal" und "QTT2_ESP_2 LoadAvg" bis heute morgen haben mindestens 30 Minuten Abstand (kann auch Zufall sein)
  
  

Ich setze den Thread mal auf gelöst und schau mir das noch eine Weile an (schrittweise auf den alten Attributwert zurück).
Genügend Tipps das im Problemfall auf der Eventseite einzugenzen sind ja gekommen 

Danke @All

[Beta-User]

Nachträge:

insbesondere wie sich ein Event zusammensetzt  --> Event = Reading-Name+Wert!

Der Vollstädnigkeit halber: Je nach Kontext sollte man unterscheiden zwischen "Event" (beinhaltet nämlich auch das, was in notify dann in $NAME landet) und $EVENT. Eigentlich ist hier "$EVENT = Reading-Name+Wert!" gemeint (wobei das auch nur dann zu 100% gilt, wenn "state"-Events als solche generiert werden...).

Ad Zufall:

Code Auswählen Erweitern

defmod td1 dummy

defmod td1log FileLog ./log/td1-%Y.log td1
attr td1log filelog-event-min-interval td1:.*:3000

set td1 x
set td1 y

Dann in das FileLog sehen....

[RalfRog]

Hallo Beta_User

Schönes Beispiel. Hab ich gleich probiert. Mit leicht unerwartetem Ergebnis.
Ich habe habe zusätzlich noch ein Reading "td1_reading" angelegt und das Attribut zeitlich verkürzt "filelog-event-min-interval  td1:.*:300"

• set td1 x  setzt das Reding "state" (und Internal STATE)
• setreading td1 td1_reading x setzt das Reading "td1_reading"

Fazit:
"set td1 x" stehen alle im Log "setreading td1 td1_reading x" nur einmal und dann wieder nach 300 Sekunden.

Ablauf:

• 5 mal set td1 1|2|3|4|5  (ändert state)
• 5 mal set td1 td1_reading  1|2|3|4|5 (ändert das manuell angelegte Reading)
  
  nach 5 Minuten warten
  
• 5 mal set td1 td1_reading  1|2|3|4|5
• 5 mal set td1 td1_reading  a|b|c|d|e

Hier der Eventmonitor und danach das Log

Code Auswählen Erweitern


Eventmonitor
2022-08-11 13:44:29.869 dummy td1 1
2022-08-11 13:44:33.425 dummy td1 2
2022-08-11 13:44:37.255 dummy td1 3
2022-08-11 13:44:40.047 dummy td1 4
2022-08-11 13:44:48.720 dummy td1 5
2022-08-11 13:46:53.695 dummy td1 td1_reading: 1
2022-08-11 13:47:10.566 dummy td1 td1_reading: 2
2022-08-11 13:47:15.325 dummy td1 td1_reading: 3
2022-08-11 13:47:20.119 dummy td1 td1_reading: 4
2022-08-11 13:47:27.367 dummy td1 td1_reading: 5

2022-08-11 13:52:30.684 dummy td1 td1_reading: 1
2022-08-11 13:52:38.139 dummy td1 td1_reading: 2
2022-08-11 13:52:44.276 dummy td1 td1_reading: 3
2022-08-11 13:52:49.422 dummy td1 td1_reading: 4
2022-08-11 13:52:53.532 dummy td1 td1_reading: 5
2022-08-11 13:53:09.399 dummy td1 td1_reading: a
2022-08-11 13:53:14.134 dummy td1 td1_reading: b
2022-08-11 13:53:23.103 dummy td1 td1_reading: c
2022-08-11 13:53:33.799 dummy td1 td1_reading: d
2022-08-11 13:53:37.415 dummy td1 td1_reading: e

Log
2022-08-11_13:44:29 td1 1
2022-08-11_13:44:33 td1 2
2022-08-11_13:44:37 td1 3
2022-08-11_13:44:39 td1 4
2022-08-11_13:44:48 td1 5
2022-08-11_13:46:53 td1 td1_reading: 1
2022-08-11_13:52:30 td1 td1_reading: 1