DbLog - Umstellung Betrieb auf SubProcess -> Tester gesucht

[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.

[SusisStrolch]

Hmm...

Code: [Auswählen]

# $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

Code: [Auswählen]

93_DbLog.pm:v5.3.0-s26750/2022-12-06

[SusisStrolch]

anyway... hier das Log (verbose 5):

Code: [Auswählen]

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:


[DS_Starter]

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:

Code: [Auswählen]

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.

[DS_Starter]

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.

[enno]

Eben die neue Version eingspielt:

Code: [Auswählen]

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

[DS_Starter]

Danke enno ... korrigiert.

[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.

[DS_Starter]

userCommand ist nun auch noch auf SubProcess umgestellt.

[SusisStrolch]

Fü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:

Code: [Auswählen]

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?

[DS_Starter]

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.

[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.

[DS_Starter]

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.

[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:

Code: [Auswählen]

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

 

[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.