DbLog - Umstellung Betrieb auf SubProcess -> Tester gesucht

DS_Starter · 27 Dezember 2022, 12:46:43

Habe die V 5.5.8 eingecheckt:

* lange (planmäßige) Meldungen werden im state zweizeilig ausgegeben

* die Meldung "Another operation is in progress. Data is stored temporarily." (zweizeilig) wird im synchronen Modus erst dann ausgegeben wenn
die vorangegangene Operation sich mit der neuen Anforderung mehr als ein zeitlicher Schwellenwert (aktuell 0.8 s) überschneidet.
Das wird die Häufigkeit der Meldung reduzieren und nur "markantere" Fälle dem User im state mitteilen.

nog76 · 28 Dezember 2022, 18:59:25

Hi,

ich habe ggf. einen Fehler in der neuen Version entdeckt.
Update auf die 5.x lief gestern problemlos durch.
Als ich heute aber meine regexp innerhalb des define angepasst habe, wird mir direkt nach dem "save"
eine Fehlermeldung angezeigt:

Code Auswählen

2022-12-28 18:50:09 DbLog myDbLog DBD::Pg::st execute failed: ERROR:  relation "history" does not exist LINE 1: INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING...                     ^ [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES ('2022-12-28 18:50:09','myDbLog','DBLOG','state: waiting for connection','state','waiting for connection',''),('2022-12-28 18:50:00','tankenPreis','JSONMOD','preis: 1.819','preis','1.819','')"] at ./FHEM/93_DbLog.pm line 2757.

Ab diesem Moment wird auch nichts mehr in die "history" Tabelle geschrieben und das Logfile mit diesen Fehlern geflutet.
Wenn ich fhem danach restarte, funktioniert wieder alles problemlos.

Aktuelle config:

Code Auswählen

defmod myDbLog DbLog /opt/fhem/config/db.conf (?i).*(temperature|humidity|preis|state):.*
attr myDbLog DbLogType Current/History
attr myDbLog asyncMode 1
attr myDbLog bulkInsert 1
attr myDbLog dbSchema fhem
attr myDbLog showproctime 1

Code Auswählen

FVERSION 93_DbLog.pm:v5.5.8-s26907/2022-12-27

Habe leider meine beiden FHEM Installationen schon auf die neue Version hochgezogen und kann daher nicht prüfen, ob das Problem schon vorher bestand. Allerdings habe ich vor einiger Zeit problemlos meine regexp "on-the-fly" anpassen können.

cortmen · 28 Dezember 2022, 19:23:57

:)Danke für das Update.

@DS_Starter

* Update:Scheint ähnlich wie nog76 seine Meldung zu sein.
Allerdings ist die Fehlermeldung eine andere..

Bitte schau einmal kurz in diesem Thread, ob da ein Zusammenhang mit den aktualisierten Modul sein kann.
Wir können gerne auch hier weiterschreiben..

https://forum.fhem.de/index.php?topic=25540.msg1254042#msg1254042

DS_Starter · 28 Dezember 2022, 19:44:48

@cortmen, nein ist kein Zusammenhang. Habe dir die Lösung geschrieben.

@nog76, deine Meldung ist ein Fehler der direkt von der Datenbank gemeldet wird:

Code Auswählen


DBD::Pg::st execute failed: ERROR:  relation "history" does not exist

Da muss ich erstmal googeln was das konkret bei Postgre bedeuten soll. Sieht mir auf den ersten Blick so aus als ob die
Verbindung zur DB verloren gegangen war.
Das Modul bringt jetzt mehr detaillierte Meldungen bei Fehlern raus. Kann sein dass sowas früher nicht aufgefallen war.
Einen direkten Zusammenhang mit dem drücken von "save" schließe ich aus. Habe gerade bei mir mit MariaDB gecheckt -> kein Problem.
Kannst mal schauen ob du den Fehler nochmal bewußt reproduzieren kannst.

DS_Starter · 28 Dezember 2022, 19:51:50

@nog76, zeig mir bitte ein list von deinem DbLog-Device.

nog76 · 28 Dezember 2022, 19:57:07

Hi, hier erstmal ein list vom device

Code Auswählen

Internals:
   COLUMNS    field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32 
   CONFIGURATION /opt/fhem/config/db.conf
   DEF        /opt/fhem/config/db.conf .*(temperature|humidity|preis|state):.*
   FD         4
   FUUID      624de2e1-f33f-1758-5c38-6b56f60aeffc8515
   FVERSION   93_DbLog.pm:v5.5.8-s26907/2022-12-27
   MODE       asynchronous
   MODEL      POSTGRESQL
   NAME       myDbLog
   NR         2
   NTFY_ORDER 50-myDbLog
   PID        313435
   REGEXP     .*(temperature|humidity|preis|state):.*
   SBP_PID    313442
   SBP_STATE  running
    STATE      connected
   TYPE       DbLog
   dbconn     Pg:database=fhemlog;host=localhost
   dbuser     qqfhemlog
   eventCount 6
   HELPER:
     COLSET     1
     DEVICECOL  64
     EVENTCOL   512
     OLDSTATE   connected
     PACKAGE    main
     READINGCOL 64
     TC         fhem.current
     TH         fhem.history
     TYPECOL    64
     UNITCOL    32
     VALUECOL   128
     VERSION    5.5.8
   OLDREADINGS:
   READINGS:
     2022-12-28 19:54:13   CacheOverflowLastNum 0
     2022-04-06 20:58:41   CacheOverflowLastState normal
     2022-12-28 19:54:43   CacheUsage      0
     2022-12-28 19:54:43   NextSync        2022-12-28 19:55:13 or when CacheUsage 500 is reached
     2022-12-28 19:54:13   background_processing_time 0.0159
     2022-12-28 19:54:13   sql_processing_time 0.0123
     2022-12-28 19:54:43   state           connected
Attributes:
   DbLogType  Current/History
   asyncMode  1
   bulkInsert 1
   dbSchema   fhem
   showproctime 1
   verbose    5

Versuche gerade das Verhalten nochmal mit verbose=5 zu reproduzieren.

nog76 · 28 Dezember 2022, 20:02:25

und hier nochmal ein Log:

Code Auswählen

2022.12.28 19:59:18 4 : DbLog myDbLog - ################################################################
2022.12.28 19:59:18 4 : DbLog myDbLog - ###              start of new Logcycle                       ###
2022.12.28 19:59:18 4 : DbLog myDbLog - ################################################################
2022.12.28 19:59:18 4 : DbLog myDbLog - number of events received: 1 of device: myDbLog
2022.12.28 19:59:18 4 : DbLog myDbLog - check Device: myDbLog , Event: state: DBD::Pg::st execute failed: ERROR:  relation "history" does not exist
LINE 1: INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING...
                    ^ [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES ('2022-12-28 19:59:18','myDbLog','DBLOG','state: waiting for connection','state','waiting for connection','')"] at ./FHEM/93_DbLog.pm line 2757.
2022-12-28 19:59:18 DbLog myDbLog waiting for connection
2022-12-28 19:59:18 DbLog myDbLog CacheUsage: 1
2022-12-28 19:59:18 DbLog myDbLog CacheOverflowLastNum: 0
2022-12-28 19:59:18 Global global MODIFIED myDbLog
2022-12-28 19:59:18 DbLog myDbLog <html>Connection parameters saved into SubProcess. <br>Connection to DB is established when it is needed.</html>
2022-12-28 19:59:18 DbLog myDbLog CacheUsage: 1
2022-12-28 19:59:18 DbLog myDbLog DBD::Pg::st execute failed: ERROR:  relation "history" does not exist LINE 1: INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING...                     ^ [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES ('2022-12-28 19:59:18','myDbLog','DBLOG','state: waiting for connection','state','waiting for connection','')"] at ./FHEM/93_DbLog.pm line 2757.

Für mich sieht es so aus, als würde nach der Änderung das Attribut "scheme" nicht mehr genutzt zu werden - in Postgres verwende ich fhem.history (also schema.tabelle).

DS_Starter · 28 Dezember 2022, 20:08:30

Zitat
Für mich sieht es so aus, als würde nach der Änderung das Attribut "scheme" nicht mehr genutzt zu werden - in Postgres verwende ich fhem.history (also schema.tabelle).

Den Verdacht hatte ich jetz auch, deswegen die Frage bzgl. List.
Ich prüfe das gerade.

DS_Starter · 28 Dezember 2022, 20:19:53

Lass bitte verbose = 5 eingestellt und führe ein "set ... stopSubProcess" aus.
In dem Log wird es viele Meldungen geben.
Interessant ist dann dieser Teil:

Code Auswählen


2022.12.28 20:15:52.711 3: DbLog LogDB1 - DB connection parameters are stored in SubProcess
2022.12.28 20:15:52.713 5: DbLog LogDB1 -  current -> current
2022.12.28 20:15:52.714 5: DbLog LogDB1 -  dbuser -> fhemtest1
2022.12.28 20:15:52.714 5: DbLog LogDB1 -  utf8 -> 1
2022.12.28 20:15:52.715 5: DbLog LogDB1 -  cm -> basic_ta:off
2022.12.28 20:15:52.715 5: DbLog LogDB1 -  model -> MYSQL
2022.12.28 20:15:52.716 5: DbLog LogDB1 -  dbconn -> mysql:database=fhemtest1;host=192.168.2.44;port=3306
2022.12.28 20:15:52.717 5: DbLog LogDB1 -  dbpassword -> xxxxxxxxx
2022.12.28 20:15:52.717 5: DbLog LogDB1 -  dbname -> fhemtest1
2022.12.28 20:15:52.718 5: DbLog LogDB1 -  dbstorepars -> 1
2022.12.28 20:15:52.718 5: DbLog LogDB1 -  history -> history

Am einfachsten ist es im Log nach "DB connection parameters are stored in SubProcess" zu suchen.

nog76 · 28 Dezember 2022, 20:27:01

Hier der Logauszug nach stopSubProcess:

Code Auswählen

2022.12.28 20:23:49 5: DbLog myDbLog - MemCache contains:  39 -> 2022-12-28 20:23:23|myDbLog|DBLOG|state: SubProcess stopped and will be automatically restarted if needed|state|SubProcess stopped and will be automatically restarted if needed|
2022.12.28 20:23:50 3: DbLog myDbLog - DB connection parameters are stored in SubProcess
2022.12.28 20:23:50 5: DbLog myDbLog -  history -> history
2022.12.28 20:23:50 5: DbLog myDbLog -  model -> POSTGRESQL
2022.12.28 20:23:50 5: DbLog myDbLog -  dbpassword -> *********
2022.12.28 20:23:50 5: DbLog myDbLog -  dbconn -> Pg:database=fhemlog;host=localhost
2022.12.28 20:23:50 5: DbLog myDbLog -  current -> current
2022.12.28 20:23:50 5: DbLog myDbLog -  cm -> basic_ta:on
2022.12.28 20:23:50 5: DbLog myDbLog -  utf8 -> 0
2022.12.28 20:23:50 5: DbLog myDbLog -  dbuser -> qqfhemlog
2022.12.28 20:23:50 5: DbLog myDbLog -  dbstorepars -> 1
2022.12.28 20:23:50 5: DbLog myDbLog -  dbname -> fhemlog

DS_Starter · 28 Dezember 2022, 20:28:53

Danke. Problem erkannt:

Zitat
2022.12.28 20:23:50 5: DbLog myDbLog - history -> history
2022.12.28 20:23:50 5: DbLog myDbLog - model -> POSTGRESQL
2022.12.28 20:23:50 5: DbLog myDbLog - dbpassword -> *********
2022.12.28 20:23:50 5: DbLog myDbLog - dbconn -> Pg:database=fhemlog;host=localhost
2022.12.28 20:23:50 5: DbLog myDbLog - current -> current

Jetzt schaue ich nach der Lösung.

nog76 · 28 Dezember 2022, 20:35:00

Super.
Nach dem Restart wird das Schema auch korrekt gelogged:

Code Auswählen

2022.12.28 20:31:10 5: DbLog myDbLog -  history -> fhem.history
...
2022.12.28 20:31:10 5: DbLog myDbLog -  current -> fhem.current

DS_Starter · 28 Dezember 2022, 21:09:33

So, denke Problem beseitigt.
Kannst du bitte die Testversion aus meinem contrib laden und restarten ?
Danach mal testen ob das Problem beseitigt ist.

In der Brower Kommandozeile:

Code Auswählen


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

oder aus dem Link im Footer.

nog76 · 28 Dezember 2022, 22:22:35

Hi,

Danke - habe die neue Version eingespielt und der Fehler scheint behoben zu sein.
Ich lasse es mal weiter über Nacht in meinem Testsystem laufen und probiere morgen das gleiche in PROD.

Danke für den schnellen Bugfix

nog76 · 29 Dezember 2022, 08:15:00

Guten Morgen,

über Nacht lief alles problemlos auf dem Testsystem durch.
Habe daher auch mein PROD-System mit der Bugfix-Version versehen - auch hier kann ich den Bug nicht mehr nachstellen.
Damit ist der Fehler aus meiner Sicht behoben (und wird ja auch schon per Update ausgespielt).

Allerdings habe ich noch ein weiteres Finding:
Bei mir steht das Attribut asyncMode auf 1 - und daher wird in den Internals bei MODE=asynchronous angezeigt.

Code Auswählen

Internals:

   FVERSION   93_DbLog.pm:v5.5.9-s26907/2022-12-27
   MODE       asynchronous

Wenn ich jedoch eine Änderung wieder in der regex vornehme, wechselt die Anzeige auf MODE=synchronous

Code Auswählen

Internals:
   FVERSION   93_DbLog.pm:v5.5.9-s26907/2022-12-27
   MODE       synchronous

Wenn ich das Attribut nochmal manuell setze, wechselt die Anzeige auch wieder auf asynchronous.