global:INITIALIZED vs. DbLog

[betateilchen]

Moin,

wie lange dauert es eigentlich, bis man nach dem Event "global:INITIALIZED" tatsächlich Daten aus DbLog abfragen kann? Gibt es irgendeinen Parameter, mit dem ich prüfen kann, ob die Datenbank bereit ist?

Mein Irrglaube war, dass ich in einem notify auf global:INITIALIZED bereits auf Daten aus DbLog zugreifen kann, um damit grafische Darstellungen außerhalb von FHEM aufzubereiten. Meine Versuche haben aber dazu geführt, dass ich beim Datenbankzugriff in einen Stapel Fehlermeldung laufe, die behaupten, die Syntax der Abfrage sei falsch. Stimmt aber definitiv nicht, denn wenn ich die gleiche Abfrage erstmalig um mindestens 16 Sekunden (durch Testen ermittelt) verzögert ausführe, funktioniert alles wie gewünscht.

[DS_Starter]

Die Grundinitialisierung erfolgt sofort nach laden der fhem.cfg:

Code Auswählen Erweitern

2023.04.30 20:42:03.844 1: Including fhem.cfg
2023.04.30 20:42:04.390 2: DbLog LogDB - Subprocess >3705< initialized ... ready for non-blocking operation
2023.04.30 20:42:04.397 2: DbLog LogDBShort - Subprocess >3706< initialized ... ready for non-blocking operation
2023.04.30 20:42:04.403 2: DbLog syslogDB - Subprocess >3707< initialized ... ready for non-blocking operation
2023.04.30 20:42:04.417 3: telnetPort: port 7072 opened
2023.04.30 20:42:04.500 3: WEB: port 8083 opened
2023.04.30 20:42:04.519 3: WEBphone: port 8084 opened
2023.04.30 20:42:04.520 3: WEBF18: port 8085 opened
....

Beim Start wird $init_done==1 (true) alle 2s geprüft um bestimmte Dinge in DbLog abzuschließen nachdem FHEM vollständig initialisiert ist.
Mit verbose 3 zeigt den Abschluß dieser Dinge dass der SubProcess zur DB connected ist:

Code Auswählen Erweitern

...
2023.04.30 20:42:37.902 3: DbLog LogDB - SubProcess connected to fhem
...

Es wäre sicherlich kein Problem ähnlich zu FHEM "global:INITIALIZED" einen Event "DbLog_<Device>:INITIALIZED"
nach Abschluß der Initialisierung auszugeben.

Allerdings verstehe ich die Frage nicht richtig weil du schreibst du greifst von außen auf die DB zu.
Das impliziert für mich, dass das DbLog-Modul dafür nicht verwendet wird.
Gleichermaßen stellt das Modul die Verfügbarkeit/Arbeitsbereitschaft der DB nicht sicher, sondern ist seinerseits selbst darauf angewiesen dass die DB bereit ist damit DbLog damit arbeiten kann.

Vermutlich habe ich aber das Problem nicht richtig erfasst. Kommmt mir auch ungewöhnlich vor dass im Fehlerfall SQL Syntaxfehler geworfen werden. Hätte eher Perl-Fehler erwartet.

Kannst du etwas näher erläutern welche Befehle du wann versuchst auzuführen ?
Dann wird es mir sicherlich etwas klarer.

Grüße,
Heiko

[betateilchen]

Hallo Heiko,

Allerdings verstehe ich die Frage nicht richtig weil du schreibst du greifst von außen auf die DB zu.
Das impliziert für mich, dass das DbLog-Modul dafür nicht verwendet wird.

Wo habe ich denn geschrieben, dass ich von aussen auf die Datenbank zugreife?
Natürlich verwende ich das DbLog und das innerhalb von FHEM.

Kannst du etwas näher erläutern welche Befehle du wann versuchst auzuführen ?
Dann wird es mir sicherlich etwas klarer.

Klar, kann ich. Es geht darum, Werte im SVG-Style aus der Datenbank zu lesen.

Code Auswählen Erweitern

define n_test notify global:INITIALIZED { initGraph() }

Im Funktionsaufruf passiert folgendes:

Code Auswählen Erweitern

sub initGraph {
  my ($sec,$min,$hour,$mday,$month,$year,$wday,$yday,$isdst) = localtime(time());
  $month = $month + 1;
  $year = $year + 1900;
  my @result = split("\n",CommandGet(undef,sprintf("logMetallDb - - %04d-%02d-%02d_00:00:00 %04d-%02d-%02d_23:59:59 mqtt_warenkorb:gesamtwert",$year,$month,$mday,$year,$month,$mday)));

... (Rest gekürzt)

und beim Ausführen des "get" kommen die Fehlermeldungen.
Die gleiche Abfrage funktioniert ein bisschen später problemlos.

[DS_Starter]

..um damit grafische Darstellungen außerhalb von FHEM aufzubereiten...

...hatte ich mißinterpretiert.

Also, ich habe dir eine Version in mein contrib geladen die einen Event auslöst sobald der SubProcess ready ist:

Code Auswählen Erweitern

2023-04-30 22:48:13.936 DbLog LogDB INITIALIZED

Der Event kommt auch wenn nach "set .. stopSubProcess" der alte SP beendet und ein neuer SP erstellt wurde.
Oder wenn ein neuer SP erstellt wird weil der alte gecrasht ist.

Aber auf diesen Event könntest du das notify ansetzen.

Allerdings verstehe ich noch nicht wieso dieser Fehler überhaupt kommt.
Alle Get-Befehle arbeiten immer noch ohne den SubProzess, d.h. blockierend im Hauptprozess bzw. evtl. mit plotfork im Falle von SVG.

Poste doch bitte noch die Fehlermitteilungen. Vllt geht mir dann noch ein Licht auf.

Edit: Ich denke ich weiß jetzt den Grund für den Fehler. Die Schemadaten (Tabellendefinitionen) sind erst vorhanden wenn die DbLog Attribute geladen wurden und dann auch intern ausgewertet wurden. Der neue Event sollte das Problem beheben wenn man daruf reagiert
 

[betateilchen]

Die Fehlermeldungen schicke ich Dir separat.

[DS_Starter]

Ok, gute Nacht. 

[betateilchen]

Ok, gute Nacht.

schön wärs... 

[DS_Starter]

Hallo Udo,

es liegt tatsächlich wie vermutet an der zu dem Zeitpunkt noch nicht abgeschlossenen internen Verarbeitung der Attribute, hier speziell des Attr dbSchema, woraus die tatsächlichen Tabellennamen gebildet werden sofern das Attr gesetzt wurde (meist bei PostgreSQL).

Ich habe die Events noch etwas ausgebaut/umgebaut um die einzelnen Status der DbLog Initialisierungsphasen besser abzubilden.
Es gibt nun folgende Events in DbLog:

Code Auswählen Erweitern

FRAME_INITIALIZED        -> das grundlegende Rahmenwerk wie Config lesen, Attr initialisieren usw. ist abgeschlossen
SUBPROC_INITIALIZED      -> der SupProcess ist einsatzbereit
SUBPROC_DISCONNECTED     -> der SupProcess wurde von der DB getrennt
SUBPROC_STOPPED          -> der SupProcess wurde gestoppt

Für deinen Einsatzfall wäre eine Reaktion auf "FRAME_INITIALIZED" ausreichend. Auf den SubProzess brauchst du ja eigentlich nicht zu warten für die Getter.
Ansonsten wäre "SUBPROC_INITIALIZED" richtig.

Die Version liegt zunächst wieder in meinem contrib zum Test.

[betateilchen]

Moin,
danke für die Analyse.

es liegt tatsächlich wie vermutet an der zu dem Zeitpunkt noch nicht abgeschlossenen internen Verarbeitung der Attribute, hier speziell des Attr dbSchema, woraus die tatsächlichen Tabellennamen gebildet werden sofern das Attr gesetzt wurde (meist bei PostgreSQL).

In meinem DbLog device sind außer room und group nur noch folgende Attribute gesetzt.

Code Auswählen Erweitern

attr logMetallDb DbLogType History
attr logMetallDb asyncMode 1
attr logMetallDb suppressAddLogV3 1

Dass es eine MySQL Datenbank ist, stand ja in den Fehlermeldungen.

Die sich aus dem Threadtitel ergebende Grundsatzfrage ist aber unbeantwortet:
Kommt global:INITIALIZED nicht eigentlich zu früh, wenn ein grundlegendes Element von FHEM - das Logging - zu diesem Zeitpunkt noch gar nicht betriebsbereit ist?

Es würde ja bedeuten, dass ich bei jedem anlegen eines notify auf FHEM-Start überlegen muss, ob ich dabei auf DbLog achten (und dann FRAME_INITIALIZED verwenden) muss oder ob ich global:INITIALIZED verwenden kann.

Deine Version in contrib werde ich heute abend testen.

[betateilchen]

Kommt global:INITIALIZED nicht eigentlich zu früh, wenn ein grundlegendes Element von FHEM - das Logging - zu diesem Zeitpunkt noch gar nicht betriebsbereit ist?

Es würde ja bedeuten, dass ich bei jedem anlegen eines notify auf FHEM-Start überlegen muss, ob ich dabei auf DbLog achten (und dann FRAME_INITIALIZED verwenden) muss oder ob ich global:INITIALIZED verwenden kann.

Eigentlich wäre ein Mechanismus wünschenswert, mit dem ein Modul im xxx_Initialize an fhem.pl melden kann, dass global:INITIALIZED erst kommen darf, wenn das Modul bzw. Device selbst ein xxx:INITIALIZED gemeldet hat.

Vielleicht kommt eine ähnliche Anforderung später auch noch von anderen Modulen - deshalb würde ich einen generischen Ansatz bevorzugen, anstatt jetzt einen patch zu bauen, der nur für DbLog funktioniert.

[betateilchen]

Code Auswählen Erweitern

FRAME_INITIALIZED        -> das grundlegende Rahmenwerk wie Config lesen, Attr initialisieren usw. ist abgeschlossen
SUBPROC_INITIALIZED      -> der SupProcess ist einsatzbereit
SUBPROC_DISCONNECTED     -> der SupProcess wurde von der DB getrennt
SUBPROC_STOPPED          -> der SupProcess wurde gestoppt
...
Die Version liegt zunächst wieder in meinem contrib zum Test.

Getestet, funktioniert, danke!

Man sollte sich aber nicht darauf verlassen, dass man den Event FRAME_INITIALIZED im EventMonitor zu sehen bekommt

Hier nochmal die Darstellung der zeitlichen Differenz:

Code Auswählen Erweitern

defmod n_test notify (global:INITIALIZED|logMetallDb:FRAME_INITIALIZED) {Debug "$NAME:$EVENT"}

>>> 2023.05.01 13:46:40.361 1: DEBUG>global:INITIALIZED
... (mehrere andere Meldungen entfernt)
2023.05.01 13:46:41.436 0: Featurelevel: 6.2
2023.05.01 13:46:41.436 0: Server started with 285 defined entities (fhem.pl:27498/2023-04-30 perl:5.032001 os:linux user:fhem pid:32549)
>>> 2023.05.01 13:46:41.921 1: DEBUG>logMetallDb:FRAME_INITIALIZED
... (mehrere andere Meldungen entfernt)
2023.05.01 13:46:42.013 3: DbLog logMetallDb - DB connection parameters are stored in SubProcess
2023.05.01 13:46:42.017 3: DbLog logMetallDb - DB connection parameters are initialized in the SubProcess

Die Zeitspanne zwischen den beiden events ist nicht vorhersehbar. Mehrere restarts lieferten völlig unterschiedliche Zeiten.

[DS_Starter]

Danke für die Rückmeldung Udo. Ich habe die Events noch in der Hilfe beschrieben und ein wenig anderweitiges Bugfixing (uninitialized Meldungen im SVG Editor) betrieben.
Die V liegt wieder im contrib und werde sie heute Abend einchecken.

Eigentlich wäre ein Mechanismus wünschenswert, mit dem ein Modul im xxx_Initialize an fhem.pl melden kann, dass global:INITIALIZED erst kommen darf, wenn das Modul bzw. Device selbst ein xxx:INITIALIZED gemeldet hat.

Vielleicht kommt eine ähnliche Anforderung später auch noch von anderen Modulen - deshalb würde ich einen generischen Ansatz bevorzugen, anstatt jetzt einen patch zu bauen, der nur für DbLog funktioniert.

Ja, da gebe ich dir recht.
Zum Beispiel gibt es ja auch die fhem.pl-Funktion notifyRegexpChanged um NOTIFYDEV zu setzen wenn möglich. Soweit ich es einschätzte (kann mich täuschen) funktioniert diese Funktion nur richtig, wenn FHEM komplett geladen ist, d.h. alle Device-Definitionen vorhanden sind. Sonst wird ein Device in NOTIFYDEV nicht gesetzt wenn dessen Definition (noch) nicht geladen ist.
Das hat jetzt mit SubProcess nichts zu tun, aber ich sehe ein Gap diesbezüglich.

Bedeutet, alle notifyRegexpChanged nutzenden Module/Devices dürften erst dann notifyRegexpChanged auführen wenn alles geladen ist, d.h. wenn global:INITIALIZED kam. Logisch wäre allerdings FHEM erst _nach_ der Ausführung von notifyRegexpChanged in allen relevanten Devices wirklich INITIALIZED. (Hoffentlich kein Denkfehler)

Bezüglich SubProcess dürften alle Module die es nutzen ein ähnliches Thema wie DbLog haben sofern es ein permanenter Prozess ist, der gleich am Anfang geforkt wird um Speicher zu sparen. Allerdings kenne ich keine. Manche starten den Sub nur temporär. Da dürfte es kein Problem geben weil erst geforkt wird wenn alles schon geladen ist. Dann kann man aber m.M. nach auch BlockingCall nutzen.

LG

[erwin]

Eigentlich wäre ein Mechanismus wünschenswert, mit dem ein Modul im xxx_Initialize an fhem.pl melden kann, dass global:INITIALIZED erst kommen darf, wenn das Modul bzw. Device selbst ein xxx:INITIALIZED gemeldet hat.

Vielleicht kommt eine ähnliche Anforderung später auch noch von anderen Modulen - deshalb würde ich einen generischen Ansatz bevorzugen, anstatt jetzt einen patch zu bauen, der nur für DbLog funktioniert.

Ja, vielleicht so, aber evtl. brauchts noch mehr Nachdenken...
Beispiel: ein IO-Modul braucht etliche Attribute, um sich zu initalisieren. deswegen wird im define ein InternalTimer... gestartet, der bekannlich erst läuft/returned, wenn global:initialized passiert ist. In der weiteren Initialisierung mit der IO-HW passieren etliche Handshakes..., was auch eine Zeit dauert. Wenn das fertig ist, wird im IO-dev 'connected' gesetzt.
Das Problem dabei (und da gibts Ähnlichkeiten zu Udo's Prob.) - Falls jetzt jemand in einem global:initialized notify ein set/get ... auslöst, dann ist das io-Modul (und die HardWare) noch nicht fertig initialisiert...
Dzt. so gelöst, das ich im IO-Modul, sub Write teste, ob IO-Modul connected ist... nicht besonders elegant, aber wenigstens gibts ein Log falls dem nicht so ist!.
Meine derzeitige Empfehlung and die USER, um das Problem zu "umgehen":

Code Auswählen Erweitern

defmod initialized_nf notify global:INITIALIZED sleep 10 quiet;; set <device> <value>;;... ob 10 sec reichen, hängt sehr von Performance/Komplexität des Environments ab!
Danke ab DS_Starter für die unermüdliche Arbeit an DbLog! 
l.g. erwin

[DS_Starter]

Hallo erwin,

da gibt es bestimmt noch einige überdenkenswerte Fälle. 

Ganz grob könnte ich mir folgenden Ablauf vorstellen:

- wenn FHEM alles geladen hat meldet es mit Event global:PREINITIALIZED das es fertig geladen hat -> entspräche dem aktuellen global:INITIALIZED
- relevante Module/Devices können darauf in ihrer NotifyFn reagieren und ihrerseits letzte Einstellungen vornehmen
- wenn sie fertig sind, melden sie den Status mit einer InitializedFn (ähnlich der etablierten DelayedShutdownFn beim Shutdown) an FHEM die Fertigmeldung zurück
- hat FHEM alle Statusmeldungen eingesammelt, wird das finale global:INITIALIZED Event ausgegeben.

Das Ganze müste noch einen Maximaltimer haben, damit FHEM beim Start nicht hängenbleibt.
Im Prinzip wäre es ein ähnliches Verfahren bei Start wie DelayedShutdown beim Stoppen von FHEM.

LG,
Heiko

[DS_Starter]

Die Version ist nun eingecheckt.

Wegen einer generischen Lösung wie angerissen müssen wir noch Rudi ins Boot holen ... vllt. liest er schon mit