DbLog - Umstellung Betrieb auf SubProcess -> Tester gesucht

Begonnen von DS_Starter, 29 November 2022, 12:54:25

Vorheriges Thema - Nächstes Thema

DS_Starter

Das hätte ich jetzt auch so nicht erwartet.
Ich glaube einen Fehler im Ablauf gefunden zu haben, korrigiert und ins contrib geladen.
Teste mal bitte mit verbose 5.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

SusisStrolch

Hmm...
# $Id: 93_DbLog.pm 26750 2022-12-06 16:38:54Z DS_Starter $

Aber das Repo zeigt Rev. 26793... von 10:20:32
Und das Modul sagt mir
93_DbLog.pm:v5.3.0-s26750/2022-12-06
Synology DS1515+, 16GB RAM, 4x 6TB WD-Red
- Docker (FHEM), MariaDB, MariaDB10, Surveillance Station
Gateways: LCG miniCUL433, LCG miniCUL868, AVR-X4000, VU-Solo SE, Kodi
ESP8266: ESPEasy (S0-Counter, Temp/Hum), Sonoff TH, Sonoff 4ch

SusisStrolch

anyway... hier das Log (verbose 5):
2022.12.06 13:06:03.559 5: DbLog logdb - DbLogExclude of "WZ.LCG.Environment": .*
2022.12.06 13:06:03.559 5: DbLog logdb - DbLogInclude of "WZ.LCG.Environment": humidity,pressure,temperature
2022.12.06 13:06:03.560 4: DbLog logdb - added event - Timestamp: 2022-12-06 13:06:03, Device: WZ.LCG.Environment, Type: LACROSSE, Event: pressure: 1018, Reading: pressure, Value: 1018, Unit:
2022.12.06 13:06:03.633 4: DbLog logdb - ################################################################
2022.12.06 13:06:03.634 4: DbLog logdb - ###         New database processing cycle - synchronous      ###
2022.12.06 13:06:03.634 4: DbLog logdb - ################################################################
2022.12.06 13:06:03.634 4: DbLog logdb - DbLogType is: Current/History
2022.12.06 13:06:03.634 4: DbLog logdb - AutoCommit mode: ON, Transaction mode: ON
2022.12.06 13:06:03.635 4: DbLog logdb - Insert mode: Array
2022.12.06 13:06:03.641 4: DbLog logdb - Primary Key used in history: none
2022.12.06 13:06:03.641 4: DbLog logdb - Primary Key used in current: DEVICE,READING
2022.12.06 13:06:03.642 4: DbLog logdb - processing event Timestamp: 2022-12-02 00:00:00, Device: Hauptzaehler, Type: ESPEASY, Event: Glitches: 657110016, Reading: Glitches, Value: 657110016, Unit:
...
2022.12.06 13:06:03.918 4: DbLog logdb - processing event Timestamp: 2022-12-02 00:13:49, Device: Teich.ModusTag, Type: ESPEASY, Event: Dusk: 61811, Reading: Dusk, Value: 61811, Unit:

2022.12.06 13:06:03.918 4: DbLog logdb - processing event Timestamp: 2022-12-02 00:13:49, Device: Teich.ModusTag, Type: ESPEASY, Event: Temp: 7.0, Reading: Temp, Value: 7.0, Unit:

2022.12.06 13:06:08.985 2: DbLog logdb - Error table history - DBD::mysql::st execute_array failed: executing 1000 generated 1 errors at ./FHEM/93_DbLog.pm line 2543.

2022.12.06 13:06:09.200 4: DbLog logdb - insert history rolled back
2022.12.06 13:06:09.860 5: DbLog logdb - DbLog_Push Returncode: DBD::mysql::st execute_array failed: executing 1000 generated 1 errors at ./FHEM/93_DbLog.pm line 2543.

2022.12.06 13:06:09.881 4: DbLog logdb - check Device: Verbrauch.Homeoffice , Event: power: 204.029879190957
2022.12.06 13:06:09.881 5: DbLog logdb - parsed Event: Verbrauch.Homeoffice , Event: power: 204.029879190957
2022.12.06 13:06:09.881 5: DbLog logdb - DbLogInclude of "Verbrauch.Homeoffice": .*
2022.12.06 13:06:09.882 4: DbLog logdb - added event - Timestamp: 2022-12-06 13:06:09, Device: Verbrauch.Homeoffice, Type: EC3000, Event: power: 204.029879190957, Reading: power, Value: 204.029879190957, Unit:
Synology DS1515+, 16GB RAM, 4x 6TB WD-Red
- Docker (FHEM), MariaDB, MariaDB10, Surveillance Station
Gateways: LCG miniCUL433, LCG miniCUL868, AVR-X4000, VU-Solo SE, Kodi
ESP8266: ESPEasy (S0-Counter, Temp/Hum), Sonoff TH, Sonoff 4ch

DS_Starter

#63
Für uns zählt erstmal nur was das Modul sagt, die Repo Versionsangabe ist jetzt nebensächlich.
Trotzdem macht mich die Ausgabe stutzig.

Ich habe die Logausgabe besser identifizierbar editiert und sie sieht jetzt so aus für den synchronen Fall verbose 5:


2022.12.06 13:41:04.751 4: DbLog LogDB1 - ################################################################
2022.12.06 13:41:04.752 4: DbLog LogDB1 - ###      New database processing cycle - SBP synchronous     ###
2022.12.06 13:41:04.753 4: DbLog LogDB1 - ################################################################
2022.12.06 13:41:04.754 5: DbLog LogDB1 - Store contains: 22731 -> 2022-12-06 13:41:04|Dum.Energy|DUMMY||T|374.1|
2022.12.06 13:41:04.755 5: DbLog LogDB1 - Store contains: 22732 -> 2022-12-06 13:41:04|Dum.Energy|DUMMY||T|374.1|
2022.12.06 13:41:04.755 5: DbLog LogDB1 - Store contains: 22733 -> 2022-12-06 13:41:04|MySTP_5000|SMAINVERTER||etotal|50162.077|
2022.12.06 13:41:04.756 5: DbLog LogDB1 - Store contains: 22734 -> 2022-12-06 13:41:04|MySTP_5000|SMAINVERTER||etoday|0.36|
2022.12.06 13:41:04.757 5: DbLog LogDB1 - Store contains: 22735 -> 2022-12-06 13:41:04|MySTP_5000|SMAINVERTER||total_pac|0.047|
2022.12.06 13:41:04.758 5: DbLog LogDB1 - Store contains: 22736 -> 2022-12-06 13:41:04|MySTP_5000|SMAINVERTER||state|0.047|
2022.12.06 13:41:05.030 5: DbLog LogDB1 - DbLogType is: Current/History
2022.12.06 13:41:05.030 4: DbLog LogDB1 - AutoCommit mode: ON, Transaction mode: ON
2022.12.06 13:41:05.030 4: DbLog LogDB1 - Insert mode: Bulk
2022.12.06 13:41:05.032 4: DbLog LogDB1 - Primary Key used in fhemtest1.history: TIMESTAMP,DEVICE,READING
2022.12.06 13:41:05.032 4: DbLog LogDB1 - Primary Key used in fhemtest1.current: DEVICE,READING
2022.12.06 13:41:05.032 5: DbLog LogDB1 - processing 22731 -> TS: 2022-12-06 13:41:04, Dev: Dum.Energy, Type: DUMMY, Event: , Reading: T, Val: 374.1, Unit:
2022.12.06 13:41:05.032 5: DbLog LogDB1 - processing 22732 -> TS: 2022-12-06 13:41:04, Dev: Dum.Energy, Type: DUMMY, Event: , Reading: T, Val: 374.1, Unit:
2022.12.06 13:41:05.032 5: DbLog LogDB1 - processing 22733 -> TS: 2022-12-06 13:41:04, Dev: MySTP_5000, Type: SMAINVERTER, Event: , Reading: etotal, Val: 50162.077, Unit:
2022.12.06 13:41:05.032 5: DbLog LogDB1 - processing 22734 -> TS: 2022-12-06 13:41:04, Dev: MySTP_5000, Type: SMAINVERTER, Event: , Reading: etoday, Val: 0.36, Unit:
2022.12.06 13:41:05.032 5: DbLog LogDB1 - processing 22735 -> TS: 2022-12-06 13:41:04, Dev: MySTP_5000, Type: SMAINVERTER, Event: , Reading: total_pac, Val: 0.047, Unit:
2022.12.06 13:41:05.032 5: DbLog LogDB1 - processing 22736 -> TS: 2022-12-06 13:41:04, Dev: MySTP_5000, Type: SMAINVERTER, Event: , Reading: state, Val: 0.047, Unit:
2022.12.06 13:41:05.032 4: DbLog LogDB1 - begin transaction
2022.12.06 13:41:05.034 4: DbLog LogDB1 - commit inserted data table fhemtest1.history
2022.12.06 13:41:05.034 3: DbLog LogDB1 - INFO - 5 of 6 events inserted into table fhemtest1.history due to PK on columns TIMESTAMP,DEVICE,READING
2022.12.06 13:41:05.034 4: DbLog LogDB1 - begin transaction
2022.12.06 13:41:05.036 4: DbLog LogDB1 - 6 of 6 events updated in table fhemtest1.current using PK on columns DEVICE,READING
2022.12.06 13:41:05.037 4: DbLog LogDB1 - commit inserted data table fhemtest1.current


Im Kopf sieht man es ist der SBP = SubProcess.
Bitte nochmal aus dem contrib ziehen und vor allem restarten. reload reicht nicht.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

DS_Starter

#64
Die set Funktionen "count" und "countNbl" sind nun ebenfalls auf SubProcess umgestellt.
countNbl ist mit count identisch und wird nicht mehr benötigt, bleibt zunächst aber wegen der Abwärtskompatibilität erhalten.

count ist dadurch per se non-blocking.

Update liegt im contrib.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

enno

Eben die neue Version eingspielt:
2022.12.06 16:00:44.266 1: PERL WARNING: "my" variable $name masks earlier declaration in same scope at ./FHEM/93_DbLog.pm line 2837, <$fh> line 32.
2022.12.06 16:00:45.324 2: DbLog MYSQL - Subprocess >326123< initialized ... ready for non-blocking operation
Einfacher FHEM Anwender auf Intel®NUC

DS_Starter

ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

DS_Starter

Die set Funktionen "deleteOldDays" und "deleteOldDaysNbl" sind nun ebenfalls auf SubProcess umgestellt.
deleteOldDaysNbl ist mit deleteOldDays identisch und wird nicht mehr benötigt, bleibt zunächst aber wegen der Abwärtskompatibilität erhalten.

Update liegt im contrib.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

DS_Starter

userCommand ist nun auch noch auf SubProcess umgestellt.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

SusisStrolch

#69
ZitatFür uns zählt erstmal nur was das Modul sagt, die Repo Versionsangabe ist jetzt nebensächlich.
Trotzdem macht mich die Ausgabe stutzig.
Da ich trotz eines neuen Downloads aus dem Repo und einem FHEM-Restart immer noch keine Fehlerbehandlung sehe:
root@fhem:/opt/fhem/FHEM# md5sum 93_DbLog.pm
9c5463f1697c386e2b6020ce49fbb979  93_DbLog.pm


Auch sehe ich im Log:
[code2022.12.07 09:50:53.758 4: DbLog logdb - ################################################################
2022.12.07 09:50:53.758 4: DbLog logdb - ###         New database processing cycle - synchronous      ###
2022.12.07 09:50:53.758 4: DbLog logdb - ################################################################
2022.12.07 09:50:53.759 4: DbLog logdb - DbLogType is: Current/History
2022.12.07 09:50:53.759 4: DbLog logdb - AutoCommit mode: ON, Transaction mode: ON
2022.12.07 09:50:53.759 4: DbLog logdb - Insert mode: Array
2022.12.07 09:50:53.783 4: DbLog logdb - Primary Key used in history: none
2022.12.07 09:50:53.783 4: DbLog logdb - Primary Key used in current: DEVICE,READING
][/code]
wobei mein Setting auf asynchron steht.
Habe ich da noch ein Attribut übersehen?

Hängt es daran das der "importCache" synchron ausgeführt wird?
Synology DS1515+, 16GB RAM, 4x 6TB WD-Red
- Docker (FHEM), MariaDB, MariaDB10, Surveillance Station
Gateways: LCG miniCUL433, LCG miniCUL868, AVR-X4000, VU-Solo SE, Kodi
ESP8266: ESPEasy (S0-Counter, Temp/Hum), Sonoff TH, Sonoff 4ch

DS_Starter

Zitat
Hängt es daran das der "importCache" synchron ausgeführt wird?

Ja, importCacheFile stelle ich gerade erst um. Hab ich auch nicht dran gedacht.  :(
Melde mich wieder wenn das erledigt ist.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

DS_Starter

Habe gerade die V 5.4.0 ins contrib geladen.

Jetzt sind auch die Befehle userCommand, exportCache und importCacheFile auf die neue Architektur angepasst.

Nun fehlt im Prinzip nur noch reduceLog bzw. reduceLogNbl ... kommt demnächst.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

DS_Starter

#72
Guten Morgen,

im contrib liegt die V 5.5.0.

Es sind nun auch  reduceLog bzw. reduceLogNbl auf SubProcess umgestellt.
Die ComRef ist angepasst.

Edit: auch das Attr timeout ist auf die neue Struktur umgesetzt.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter

SusisStrolch

Moin,

Habe die 5.5 eingespielt, die Lage ist jedoch unverändert.

Ablauf:
  importCache "Cache-Datei mit UTF-8 Fehler" um Fehler auf der mysql-Seite zu provizieren.

Erwartungshaltung:   

  • Daten des MemCache (bzw. für diesen Commit verwendeten Buffers) werden in ein Cache-File geschrieben
  • der fehlerhafte MemCache wird weggeworfen

Hier der entsprechende Level 5 Trace:
2022.12.09 12:02:23.089 3: DbLog logdb - 33 rows read from ./log/cache_logdb_2022-12-02_00:10:05 into temporary Memory store
2022.12.09 12:02:23.090 5: DbLog logdb - DbLogType is: history
2022.12.09 12:02:23.091 4: DbLog logdb - AutoCommit mode: OFF, Transaction mode: OFF
2022.12.09 12:02:23.092 4: DbLog logdb - Insert mode: Array
2022.12.09 12:02:23.100 4: DbLog logdb - Primary Key used in history: none
2022.12.09 12:02:23.101 4: DbLog logdb - Primary Key used in current: DEVICE,READING
2022.12.09 12:02:23.101 4: DbLog logdb - add stored data: 0 -> 2022-12-02 00:10:05|Umwaelzung|ESPEASY|Pumpe: 0.0|Pumpe|0.0|
2022.12.09 12:02:23.101 4: DbLog logdb - add stored data: 1 -> 2022-12-02 00:10:05|Umwaelzung|ESPEASY|Ruecklauf: 15.2|Ruecklauf|15.2|
2022.12.09 12:02:23.102 4: DbLog logdb - add stored data: 2 -> 2022-12-02 00:10:05|Umwaelzung|ESPEASY|state: Pumpe: 0.0 Rueck: 15.2 Vorla: 33.3 delta: 0.0|state|Pumpe: 0.0 Rueck: 15.2 Vorla: 33.3 delta: 0.0|
2022.12.09 12:02:23.102 4: DbLog logdb - add stored data: 3 -> 2022-12-02 00:10:05|Umwaelzung|ESPEASY|Vorlauf: 33.3|Vorlauf|33.3|
2022.12.09 12:02:23.102 4: DbLog logdb - add stored data: 4 -> 2022-12-02 00:10:05|Verbrauch.Warmwasser|EC3000|power: 0.779215177016016|power|0.779215177016016|
2022.12.09 12:02:23.103 4: DbLog logdb - add stored data: 5 -> 2022-12-02 00:10:06|EMS_Boiler|MQTT2_DEVICE|serviceCode: 0�|serviceCode|0�|
2022.12.09 12:02:23.120 5: DbLog logdb - processing 32 -> TS: 2022-12-02 00:10:27, Dev: Hof.3erDose, Type: MQTT2_DEVICE, Event: Wifi_SSId: SusiconStrolch, Reading: Wifi_SSId, Val: SusiconStrolch, Unit:

2022.12.09 12:02:23.143 2: DbLog logdb - Error table history - DBD::mysql::st execute_array failed: executing 33 generated 1 errors at ./FHEM/93_DbLog.pm line 2908.

2022.12.09 12:02:23.160 4: DbLog logdb - ################################################################
2022.12.09 12:02:23.161 4: DbLog logdb - ###              start of new Logcycle                       ###
2022.12.09 12:02:23.161 4: DbLog logdb - ################################################################
2022.12.09 12:02:23.161 4: DbLog logdb - number of events received: 1 of device: logdb


Ergebnis:   

  • Daten des MemCache werden nicht geschrieben
  • der fehlerhafte MemCache wird weggeworfen
 
Synology DS1515+, 16GB RAM, 4x 6TB WD-Red
- Docker (FHEM), MariaDB, MariaDB10, Surveillance Station
Gateways: LCG miniCUL433, LCG miniCUL868, AVR-X4000, VU-Solo SE, Kodi
ESP8266: ESPEasy (S0-Counter, Temp/Hum), Sonoff TH, Sonoff 4ch

DS_Starter

An der Stelle hatte ich noch nichts gemacht.
Aber jetzt V 5.5.1 im contrib. Restart erforderlich !

Im Array-Modus (default) und abgeschalteter Transaktion werden die fehlerhaften Daten nicht in die DB geschrieben (die anderen commited) und mit verbose 4 protokolliert, aber nicht an den Cache zurück gegeben.
ESXi@NUC+Debian+MariaDB, PV: SMA, Victron MPII+Pylontech+CerboGX
Maintainer: SSCam, SSChatBot, SSCal, SSFile, DbLog/DbRep, Log2Syslog, SolarForecast,Watches, Dashboard, PylonLowVoltage
Kaffeekasse: https://www.paypal.me/HMaaz
Contrib: https://svn.fhem.de/trac/browser/trunk/fhem/contrib/DS_Starter