[DBLog] Wunschliste: Watchdog, Meldungen im state

Christoph Morrison · 14 Februar 2021, 22:14:57

Hallo DS_Starter,

ich hätte Ideen für DBLog.

1. Ich hatte gestern Probleme mit der Datenbank, DBLog konnte keine Daten mehr dort hin schreiben. Der Cache füllte sich und füllte sich - und irgendwann stieg FHEM ohne weiteren Speicher aus. Ich habe mir dann, bis ich das DB-Problem behoben hatte, einen DOIF-Watchdog geschrieben, der bei einer bestimmten CacheUsage einen export mit purge macht und mich benachrichtigt. Das hat soweit funktioniert. Bestände denn die Chance, dass du so einen Watchdog direkt in DBLog einbaust? Ich stelle mir das so vor, dass man weiteres Attribut setzen kann, das eine Schwelle definiert, ab dem ein export mit purge gemacht wird. In ein Reading sollte dann eine passende Meldung geschrieben werden, damit das monitoren kann. So hält man das System auch bei Fehlern am Laufen.

2. Beim Überlegen/Watchdog schreiben ist mir aufgefallen, dass state nicht immer "connected" ist, ist ja auch klar. Könntest du diesen Wert in ein eigenes Reading schreiben? Ich habe einen Watchdog auf den state der wenn nicht connected mir eine Nachricht schickt - dummerweise löste der auch aus, wenn z.B. Status von NextSync oder Import in den state geschrieben werden.

Gruß
Christoph

DS_Starter · 15 Februar 2021, 15:21:52

Hallo Christoph,

Zitat
Bestände denn die Chance, dass du so einen Watchdog direkt in DBLog einbaust? Ich stelle mir das so vor, dass man weiteres Attribut setzen kann, das eine Schwelle definiert, ab dem ein export mit purge gemacht wird. In ein Reading sollte dann eine passende Meldung geschrieben werden, damit das monitoren kann. So hält man das System auch bei Fehlern am Laufen.

Ja, das sollte gut machbar sein.

Zitat
... dass state nicht immer "connected" ist, ist ja auch klar. Könntest du diesen Wert in ein eigenes Reading schreiben?

Wäre das nicht schon gegeben wenn ich den obigen Zustand in ein separates Reading schreibe oder falsch verstanden ?

Hatte mich mich in letzter Zeit ein bisschen um was anderes gekümmert und FHEM etwas vernachlässigt.
Muss ich mal wieder etwas in den Focus rücken.

Grüße,
Heiko

Christoph Morrison · 15 Februar 2021, 16:51:17

Hallo Heiko,

freut mich, dass du meine Ideen aufgreifen möchtest. Ich war sehr angenehm von der importCache-Funktion überrascht, die ich so gar nicht auf dem Schirm hatte - so habe ich all die weggesicherten Logeinträge einfach wieder einspielen können.

Zitat von: DS_Starter am 15 Februar 2021, 15:21:52
Wäre das nicht schon gegeben wenn ich den obigen Zustand in ein separates Reading schreibe oder falsch verstanden ?

Also ich stelle mir das so vor:
Reading state → Allgemeine Statusinfos, die sich auch ändern können, aber vorzugsweise nur kurze Infos und keine lange Prosa wie aktuell bei NextSync oder einem purge - das ist eher was fürs Log finde ich. Ich versuche Readings immer als singulären Wert zu halten um sie leichter auswerten zu können.

Reading connection o.ä. → Zustand der DB-Verbindung, also connected / disconnected

Gruß
Christoph

DS_Starter · 15 Februar 2021, 20:29:37

ZitatIch war sehr angenehm von der importCache-Funktion überrascht, die ich so gar nicht auf dem Schirm hatte - so habe ich all die weggesicherten Logeinträge einfach wieder einspielen können.

so war es gedacht.

EIn zusätzliches Reading ist kein Problem denke ich. Mir schwebt da zum Beipiel ein "cacheOverflow" mit den Werten "no" / "yes" vor um den Zusatand zu signalisieren.

Beim state bin ich mir nach längerem Nachdenken nicht so sicher. Ich vermute dass sowohl im DbLog selbst als auch im DbRep verschiedene state-Zustände zur Steuerung interner Abläufe ausgewertet werden. Aber das muß ich genauer prüfen bevor ich an den Meldungen im state etwas ändere.

Was den cache Füllgrad angeht ... ich kann an dieser Stelle nur die Anzahl der Event-Datensätze in einem Attr einstellbar machen weil ich die zählen kann. Damit der User eine Vorstellung hat wieviel Datensätze zum Beispiel ein MB RAM belegen wäre es natürlich gut da mal eine Messung zu machen. Mit fehlt allerdings eine Idee wie man sowas einigermaßen gut abschätzen kann.

Grüße,
Heiko

Christoph Morrison · 15 Februar 2021, 20:44:24

Zitat von: DS_Starter am 15 Februar 2021, 20:29:37
EIn zusätzliches Reading ist kein Problem denke ich. Mir schwebt da zum Beipiel ein "cacheOverflow" mit den Werten "no" / "yes" vor um den Zusatand zu signalisieren.

Was den cache Füllgrad angeht ... ich kann an dieser Stelle nur die Anzahl der Event-Datensätze in einem Attr einstellbar machen weil ich die zählen kann. Damit der User eine Vorstellung hat wieviel Datensätze zum Beispiel ein MB RAM belegen wäre es natürlich gut da mal eine Messung zu machen. Mit fehlt allerdings eine Idee wie man sowas einigermaßen gut abschätzen kann.

Ich fasse mal die zwei Absätze zusammen - falls sie nicht zusammen gehören, korrigiere mich bitte.

Ich würde das einfach über ein Attribut konfigurierbar machen - wenn kein Attribut, z.B. cacheOverflowThreshold, gesetzt ist, macht DBLog nix und wenn, dann wird halt ab diesem Wert ein lokaler Dump gemacht. Wenn der Wert kleiner ist als cacheLimit, wird er auf diesen intern angehoben. Signalisieren kann man das eigentlich ruhig im state oder in einem cacheLastSaved-Reading (Wert dann die Anzahl der gesicherten Einträge, TS bekommt man ja über das Reading). Darauf kann man dann auch ein Notify triggern.

Zitat von: DS_Starter am 15 Februar 2021, 20:29:37
Beim state bin ich mir nach längerem Nachdenken nicht so sicher. Ich vermute dass sowohl im DbLog selbst als auch im DbRep verschiedene state-Zustände zur Steuerung interner Abläufe ausgewertet werden. Aber das muß ich genauer prüfen bevor ich an den Meldungen im state etwas ändere.

Für mich wäre das auch nur optional, so lange der Connection-Status in einem eigenen Reading persistiert. Wichtiger fände ich eh den Overflow-Watchdog.

DS_Starter · 15 Februar 2021, 20:54:19

Zitat
Ich würde das einfach über ein Attribut konfigurierbar machen - wenn kein Attribut, z.B. cacheOverflowThreshold, gesetzt ist, macht DBLog nix und wenn, dann wird halt ab diesem Wert ein lokaler Dump gemacht. Wenn der Wert kleiner ist als cacheLimit, wird er auf diesen intern angehoben. Signalisieren kann man das eigentlich ruhig im state oder in einem cacheLastSaved-Reading (Wert dann die Anzahl der gesicherten Einträge, TS bekommt man ja über das Reading). Darauf kann man dann auch ein Notify triggern.

Ja so in der Art hatte ich es auch verstanden und würde es versuchen so umzusetzen.

Was ich meinte war die Tatsache, dass der User in dem neuen Attribut nur die Anzahl der Datensätze im Cache angeben kann die dann als Schwellenwert für den lokalen Dump gelten soll.
Was einem fehlt ist eine Beziehung zu dem RAM den man dem Cache für einen solchen Schwellenwert zugestehen will. (Damit der lokale Dump vor einem RAM-Engpass greift).
Naja, vielleicht ist das auch nicht nötig. Wenn halt 50.000 Sätze im Cache sind, geht man mal davon aus dass etwas nicht stimmt.

Christoph Morrison · 15 Februar 2021, 21:04:39

Zitat von: DS_Starter am 15 Februar 2021, 20:54:19
Naja, vielleicht ist das auch nicht nötig. Wenn halt 50.000 Sätze im Cache sind, geht man mal davon aus dass etwas nicht stimmt.

Das ist halt wirklich sehr abhängig vom System und dem was sonst noch so läuft, deshalb würde ich da gar keine Angaben oder Vorschläge machen. Ich weiß nicht mal genau, bei welchem Cache-Füllgrad mein FHEM neu gestartet wurde, aber ich gehe einfach aktuell davon aus, dass wenn cacheLimit * 1,5 Einträge vorhanden sind, irgendwas schief gelaufen ist. Ein harter Wert wäre aber auch völlig in Ordnung.

DS_Starter · 15 Februar 2021, 21:12:32

Zitataber ich gehe einfach aktuell davon aus, dass wenn cacheLimit * 1,5 Einträge vorhanden sind, irgendwas schief gelaufen ist.

Naja, nicht unbedingt. Wenn meine große DB auf der Synology gesichert wird läuft schonmal eine Stunde lange nichts rein und wird in der Zeit gecacht. Die 1.5 mal würden schnell gerissen.

Aber das soll jetzt kein Hindernis sein. Bei Einsatz eines solchen Setups muss/sollte sich der User eben ein paar Gedanken zu seinem System machen und die Zusammanhänge verscuehn zu verstehen. Ich tue mein Bestes um in der Commandref hinreichende Erläuterungen zu geben.

Melde mich wenn ich etwas für den ersten Test gebaut habe. Dauert aber vermutlich bis zum WE, bin die Woche fast jeden Abend mit anderen Dingen geblockt.

Christoph Morrison · 15 Februar 2021, 21:14:51

Danke dir.

DS_Starter · 20 Februar 2021, 16:26:59

Hallo Christoph,

ich habe den Request jetzt mal umgesetzt und eine Version in mein contrib geschoben.
Es gibt ein neues Attr cacheOverflowThreshold:

cacheOverflowThreshold

attr <device> cacheOverflowThreshold <n>
Legt im asynchronen Logmodus den Schwellenwert von <n> Datensätzen fest, ab dem der Cache Inhalt in ein File exportiert wird anstatt die Daten in die Datenbank zu schreiben.
Die Funktion entspricht dem Set-Kommando "exportCache purgecache" und verwendet dessen Einstellungen.
Mit diesem Attribut kann eine Überlastung des Serverspeichers verhindert werden falls die Datenbank für eine längere Zeit nicht verfügbar ist (z.B. im Fehler- oder Wartungsfall). Ist der Attributwert kleiner oder gleich dem Wert des Attributs "cacheLimit", wird dieser Wert für "cacheOverflowThreshold" verwendet.
In diesem Fall wird der Cache immer in ein File geschrieben anstatt in die Datenbank. Somit kann diese Einstellung bewußt genutzt werden, um die Daten zu einem späteren Zeitpunkt mit dem Set-Kommando "importCachefile" in die Datenbank zu reimportieren.

Es gibt im AsynchMode nun noch das Reading CacheOverflowLastNum. Dort wird immer die letzte Anzahl der das eingestellte cacheLimit überschrittenen Anzahl von Datensätzen im Cache eingetragen. Damit sieht man immer ob und wenn ja um wieviel das Limit überschritten wurde und kann sich daraus etwas bauen zur Benachrichtigung, what ever.
Dieses Reading wird unabhängig von der Verwendung des Attr cacheOverflowThreshold befüllt.

Die V kannst du einfach so runterladen:

Code Auswählen


"wget -qO ./FHEM/93_DbLog.pm https://svn.fhem.de/fhem/trunk/fhem/contrib/DS_Starter/93_DbLog.pm"

Danach ist ein Restart nötig, ich habe auch gleich die Prototypen rausgehauen und ein paar andere Kleinigkeiten.

Jeder andere der den Thread liest ist natürlich auch herzlich zum Test eingeladen.

Grüße,
Heiko

Christoph Morrison · 20 Februar 2021, 21:58:50

Ich habe leider die nächsten paar Tage wenig Zeit zum Testen (und bin nicht vor Ort und dann bastele ich auch nicht zu Hause rum). Denke ich werde Mitte nächster Woche dazu kommen.

DS_Starter · 21 Februar 2021, 17:25:33

Kein Stress Christoph. Hat ja keine Eile, ich teste auch auf meinen Systemen.
Es ist noch ein Reading CacheOverflowLastState dazugekommen. Es hat die Status "normal" und "exceeded". Ist so ein bisschen das "overload" von Homematic

Damit kann man sich schnell ein Telegram, Email oder Synology Chat zusenden wenn der Zustand eintritt.

Grüße,
Heiko

DS_Starter · 27 Februar 2021, 13:16:24

Hallo Christoph,

konntest du schon etwas testen.
Bei läuft es einwandfrei.

Grüße,
Heiko

Christoph Morrison · 27 Februar 2021, 16:33:09

Leider nein, die Gartensaison musste etwas zeitnaher starten. Vielleicht heute Abend noch.

Risiko · 28 Februar 2021, 19:53:26

Hallo DS_Starter.

Danke für die Funktionalität. Finde ich super.
Habe kurz getestet. Der Export funktioniert prinzipiell.
Da ich aus deiner Erläuterung das Funktionsprinzip leider nicht ganz genau verstanden habe, kurz was mir aufgefallen ist.

Der Export erfolgt genau beim erreichen von cacheOverflowThreshold (cacheOverflowThreshold>cacheLimit) und nicht wie gedacht bei cacheLimit+cacheOverflowThreshold.
Wenn cacheOverflowThreshold < cacheLimit ist, wird genau bei cacheLimit exportiert.

CacheOverflowLastNum war aber immer Null und CacheOverflowLastState immer normal. Soll wohl nicht so sein,oder?

Nochmal Danke für den auto Export.

Risiko.

DS_Starter · 28 Februar 2021, 20:13:43

Hallo Risiko,

Zitat
Der Export erfolgt genau beim erreichen von cacheOverflowThreshold (cacheOverflowThreshold>cacheLimit) und nicht wie gedacht bei cacheLimit+cacheOverflowThreshold.

Der Export erfolgt wenn cacheOverflowThreshold >= cacheLimit erreicht wird. Die Annahme cacheLimit+cacheOverflowThreshold ist nicht richtig.

ZitatWenn cacheOverflowThreshold < cacheLimit ist, wird genau bei cacheLimit exportiert.

Wenn das Attr cacheOverflowThreshold < Attr cacheLimit ist, wird cacheOverflowThreshold = cacheLimit gesetzt und deshalb ist es richtig dass genau bei/ab cacheLimit exportiert wird.

Zitat
CacheOverflowLastNum war aber immer Null und CacheOverflowLastState immer normal. Soll wohl nicht so sein,oder?

Also im Normalfall, d.h. im Normalbetrieb ist CacheOverflowLastNum immer Null und CacheOverflowLastState immer normal.
Die Werte ändern sich wenn die Überschreitung stattfindet, aber auch nur solange bis der Normalzustand wieder hergestellt ist.
Es werden entsprechenden Logeinträge bzw. Events generiert und darauf reagieren zu können mit einer Mail/Telegram etc.
Bei meinen Tests ist es auch so, z.B.:

Code Auswählen


2021.02.28 04:02:33.057 2: DbLog LogDB1 -> WARNING - Cache is exported to file instead of logging it to database
2021.02.28 04:11:39.312 2: DbLog LogDB1 -> WARNING - Cache is exported to file instead of logging it to database
2021.02.28 04:20:03.156 2: DbLog LogDB1 -> WARNING - Cache is exported to file instead of logging it to database
2021.02.28 04:28:32.836 2: DbLog LogDB1 -> WARNING - Cache is exported to file instead of logging it to database
2021.02.28 04:36:50.839 2: DbLog LogDB1 -> WARNING - Cache is exported to file instead of logging it to database

Grüße,
Heiko

DS_Starter · 04 März 2021, 21:01:26

Ich habe die Version jetzt nach rund 2 Wochen Testlauf finalisiert bzgl. (engl.) Hilfe und eingecheckt.

LG,
Heiko

Christoph Morrison · 04 März 2021, 22:08:38

Ja, inzwischen hatte ich es mir auch angeschaut und sah mit manuellen DB-offline-Schalten auch gut aus. Danke dir!

Frank_Huber · 23 April 2021, 07:54:40

Morgen Heiko,

Die Nacht ist mein mySQL Server abgeschmiert.
DbLog hat dann wie konfiguriert in Dateien exportiert .

Das Problem jetzt ist, die Dateien sind leer. 0 byte Größe.
Hast Du ne Idee? FHEM und Buster wurden vorgestern aktualisiert.

list:

Code Auswählen

Internals:
   .FhemMetaInternals 1
   COLUMNS    field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32 
   CONFIGURATION ./db_mysql.conf
   DEF        ./db_mysql.conf .*:.*
   FUUID      5c5334ae-f33f-c13c-5275-6fb8097e577fd169
   FVERSION   93_DbLog.pm:v4.12.1-s24180/2021-04-07
   MODE       asynchronous
   MODEL      MYSQL
   NAME       logdb
   NR         279
   NTFY_ORDER 50-logdb
   PID        862
   REGEXP     .*:.*
   STATE      connected - 14189467 Zeilen
   TYPE       DbLog
   UTF8       1
   dbconn     mysql:database=fhem;host=192.168.12.212;port=3306
   dbuser     fhemuser
   .attraggr:
   .attrminint:
   HELPER:
     COLSET     1
     DEVICECOL  64
     EVENTCOL   512
     OLDSTATE   connected
     PACKAGE    main
     READINGCOL 64
     TC         current
     TH         history
     TYPECOL    64
     UNITCOL    32
     VALUECOL   128
     VERSION    4.12.1
   Helper:
     DBLOG:
       CacheUsage:
         logdb:
           TIME       1619157117.51704
           VALUE      8
       countHistory:
         logdb:
           TIME       1619138700.46488
           VALUE      14189467
   READINGS:
     2021-04-23 07:51:57   CacheOverflowLastNum 0
     2021-04-23 05:59:47   CacheOverflowLastState normal
     2021-04-23 07:51:59   CacheUsage      1
     2021-04-23 07:51:57   NextSync        2021-04-23 07:52:27 or if CacheUsage 50 reached
     2021-04-23 02:45:00   countHistory    14189467
     2021-04-23 07:41:04   lastCachefile   
     2021-04-23 07:51:57   state           connected

Attributes:
   DbLogExclude .*
   DbLogInclude countHistory,CacheUsage
   DbLogSelectionMode Exclude/Include
   DbLogType  History
   asyncMode  1
   bulkInsert 1
   cacheEvents 2
   cacheLimit 50
   cacheOverflowThreshold 500
   group      MySQL
   room       SYSTEM
   stateFormat state - countHistory Zeilen

Danke & Grüße
Frank

DS_Starter · 23 April 2021, 09:01:40

Morgen Frank,

hab jetzt eine Weile drüber nachgedacht, aber noch keine wirkliche Idee.
War vielleicht deine Platte voll ?

Es müssten Meldungen im Log auftauchen:

Zitat
WARNING - Cache is exported to file instead of logging it to database

Dummerweise hab ich gerade gesehen, dass evtl. Fehlermeldungen im Schreibprozess der Dateien nicht zurückgeldet/ausgewertet werden um sie anzuzeigen. Das muß ich ändern.
Ändert aber nichts am Sachverhalt, nur an der Logausgabe.

Sonst irgendwelche Fehler im Log zu sehen ?

LG,
Heiko

Frank_Huber · 23 April 2021, 10:21:12

Oh,

AUf der SD sind 9,5 von 16GB frei.
ins Log hab ich heut früh gar nicht geschaut. Sorry. hätte ich gleich machen können.
Laut Log hat er es zwei mal ausgeführt. Also die Datei mit den Einträgen wieder durch eine leere überschrieben.

wäre es hier evtl Sinnvoll bereits existierende Dateien nicht zu überschreiben?
Ist zwar eigentlich unwahrscheinlich durch den Zeitstempel, aber passieren kann es doch. wie bei mir heute...

Log:

Code Auswählen

2021.04.23 05:56:51.549 2: DbLog logdb -> WARNING - Cache is exported to file instead of logging it to database
2021.04.23 05:56:51.554 3: DbLog logdb: 506 cache rows exported to ./log/cache_logdb_2021-04-23_05-56-51.
2021.04.23 05:56:51.555 3: DbLog logdb: Cache purged after exporting rows to ./log/cache_logdb_2021-04-23_05-56-51.
2021.04.23 05:56:51.575 2: DbLog logdb -> WARNING - Cache is exported to file instead of logging it to database
2021.04.23 05:56:51.578 3: DbLog logdb: 0 cache rows exported to ./log/cache_logdb_2021-04-23_05-56-51.
2021.04.23 05:56:51.581 3: DbLog logdb: Cache purged after exporting rows to ./log/cache_logdb_2021-04-23_05-56-51.

Danke & Grüße
Frank

DS_Starter · 23 April 2021, 10:41:46

Ah ja das ist ja blöd. Vermutlich wäre es gut wenn ich den Timestamp im Namen um Millisekunden erweitere. Dann kann das nicht mehr passieren.

Frank_Huber · 23 April 2021, 10:46:19

Ja, das wäre auch ne einfache Lösung für das Überschreiben.

Aber warum wurde es zwei mal ausgeführt? Übrigens bei jeder der Export Dateien 2 mal.

DS_Starter · 23 April 2021, 10:58:40

Das ist eine sehr gute Frage, die ich mir auch schon gestellt habe.
Auf meinem Testsystem provoziere ich es jede Nacht:

Code Auswählen

2021.04.22 03:17:59.973 2: DbLog LogDB1 -> WARNING - Cache is exported to file instead of logging it to database
2021.04.22 03:32:54.566 2: DbLog LogDB1 -> WARNING - Cache is exported to file instead of logging it to database
2021.04.22 03:46:35.145 2: DbLog LogDB1 -> WARNING - Cache is exported to file instead of logging it to database
2021.04.22 04:00:36.342 2: DbLog LogDB1 -> WARNING - Cache is exported to file instead of logging it to database

Und die Filegrößen dazu:

Code Auswählen


-rwxrwxrwx  1 fhem dialout  514782 Apr 22 03:17  cache_LogDB1_2021-04-22_03-17-59
-rwxrwxrwx  1 fhem dialout  532025 Apr 22 03:32  cache_LogDB1_2021-04-22_03-32-54
-rwxrwxrwx  1 fhem dialout  525589 Apr 22 03:46  cache_LogDB1_2021-04-22_03-46-35
-rwxrwxrwx  1 fhem dialout  506599 Apr 22 04:00  cache_LogDB1_2021-04-22_04-00-36

Wie man sieht wird da nichts doppelt geschrieben. Hmm...

Christoph Morrison · 23 April 2021, 11:05:30

Niedriges cacheLimit (50) oder cacheOverflowThreshold (500), das dazu führt, dass innerhalb der gleichen Minute zwei Logfiles (oder mehr, je nach Logging-Last) produziert werden?

DS_Starter · 23 April 2021, 11:07:59

In der gleichen _Sekunde_ sogar.

Frank_Huber · 23 April 2021, 11:32:28

Zitat von: Christoph Morrison am 23 April 2021, 11:05:30
Niedriges cacheLimit (50) oder cacheOverflowThreshold (500), das dazu führt, dass innerhalb der gleichen Minute zwei Logfiles (oder mehr, je nach Logging-Last) produziert werden?

Ich verstehe das so:
- bei spätestens 50 Einträgen wird in die DB geschrieben. also cycle oder max 50.
- Wenn 500 aufgelaufen sind export.

Normalerweise sind auf dieser Instanz im Schnitt ca. 10 Einträge im Cache.