DbLog - Umstellung Betrieb auf SubProcess -> Tester gesucht

[SusisStrolch]

@SusisStrolch ... gibt es noch irgendwelche Testergebnisse mit deinem Szenario ?

Ansonsten wäre die aktuell im contrib liegende Version soweit fertig um damit life gehen zu können falls mir nicht noch etwas auf/einfällt.

Nein - leider nicht. Hatte ein wenig Vorweihnachtstress (Releasegang 9.1. in der Firma) und deshalb keine Zeit meine Fehler zu testen.
Die Spezialversion lief nicht - da hat FHEM beim Start einen Fehler geworfen und das Modul direkt gelöscht.
Deshalb bin ich noch auf der 5.5.3 - denke aber, dass ich morgen zu einem Test mit der .6 komme.

[DS_Starter]

@Sany, Frank_Huber ... danke für euer Feedback !

@SusisStrolch weißt du noch den Fehler ?

[SusisStrolch]

Nun, ich weiß zumindest wie das Problem zustande kam.
Ich hatte die .pm nach FHEM kopiert und danach ein "shutdown restart" ausgeführt.

Code Auswählen Erweitern

2022.12.14 08:27:31.435 4: DbLog logdb - added event - Timestamp: 2022-12-14 08:27:31, Device: global, Type: GLOBAL, Event: SHUTDOWN, Reading: state, Value:
SHUTDOWN, Unit:
2022.12.14 08:27:31.439 0: Server shutdown
2022.12.14 08:27:31.441 4: ESPEasy Hauptzaehler: Shutdown requested
2022.12.14 08:27:36.078 4: DbLog logdb - ################################################################
2022.12.14 08:27:36.078 4: DbLog logdb - ###              start of new Logcycle                       ###
2022.12.14 08:27:36.079 4: DbLog logdb - ################################################################
...
2022.12.14 08:27:36.531 4: DbLog logdb - ################################################################
2022.12.14 08:27:36.531 4: DbLog logdb - ###              start of new Logcycle                       ###
2022.12.14 08:27:36.531 4: DbLog logdb - ################################################################
2022.12.14 08:27:36.532 4: DbLog logdb - number of events received: 1 of device: EMS_Boiler
2022.12.14 08:27:36.532 4: DbLog logdb - check Device: EMS_Boiler , Event: curFlowTemp: 64.2


Da keine Rückmeldung im Log kam habe ich in meiner grenzenlosen Geduld nach 2min einen "systemctl restart" ausgeführt.

Code Auswählen Erweitern

Dec 14 08:29:22 fhem systemd[1]: Stopped FHEM Home Automation.
Dec 14 08:29:22 fhem systemd[1]: Starting FHEM Home Automation...
Dec 14 08:29:24 fhem systemd[1]: Started FHEM Home Automation.


welcher dann zu diesem Logeintrag führte:

Code Auswählen Erweitern


2022.12.14 08:29:26.063 1: reload: Error:Modul 93_DbLog deactivated:

2022.12.14 08:29:28.653 1: Verbrauch.Multimedia: no I/O device
2022.12.14 08:29:28.659 1: Verbrauch.Warmwasser: no I/O device
2022.12.14 08:29:28.667 1: Verbrauch.Waschmaschine: no I/O device
2022.12.14 08:29:41.390 1: define Rep.logdb.fhem DbRep logdb: The specified DbLog-Device "logdb" doesn't exist.
2022.12.14 08:29:41.522 1: define Rep.logdb.knowhere DbRep logdb: The specified DbLog-Device "logdb" doesn't exist.

Danach war das Modul gelöscht...

[DS_Starter]

2022.12.14 08:29:26.063 1: reload: Error:Modul 93_DbLog deactivated:
 

Sieht so aus, als hätte danach ein Fehler ausgegeben werden sollen der allerdings nur "leer" war.

Vllt. war der Download des Moduls nicht ok.
Naja, wahrscheinlich müssig jetzt noch darüber nachzudenken.

Danach war das Modul gelöscht...

Ich habe deswegen im global Device das Attr autosave = 0 gesetzt.
Normalerweise deaktiviert fhem nach einem Fehler beim Start die autosave Funktion selbständig.
Vllt. klappt das manchmal nicht so wie es soll, z.B. wenn wie oben der Fehler "leer" ist.
D.h. wenn du nach einem fehlerhaften Start _nicht_ "save" drückst, bleiben die Device Konfigurationen erhalten.
Den Fehler beseitigen und fhem neu starten bringt deine Konfiguration wieder zurück.

Mit autosave = 0 habe ich die Kontrolle über mein System, geht eben ein bisschen auf Kosten des Komforts.

[DS_Starter]

Und wie sieht es bei dir eigentlich mit der V 5.5.6 aus ?

[erwin]

Hi,
ich hab jetzt auch die aktuelle version auf dem produktiv-system - bisher alles Bestens!
Danke!
erwin

[thburkhart]

etwas offtopic:

ich habe irgendwann mal folgendes zum Datenbank-Backup definiert

Code Auswählen Erweitern

[code]define at_dblog_THBDump at *04:00:00 set Report_DumpsRows dumpMySQL clientSide
attr at_dblog_THBDump alias THBDUMP 4:00
attr at_dblog_THBDump room DBLog,xTimer
#   COMMAND    set Report_DumpsRows dumpMySQL clientSide
#   DEF        *04:00:00 set Report_DumpsRows dumpMySQL clientSide
#   FUUID      61daea6a-f33f-21fb-b2e6-a7e04cc6a8d5bed2
#   NAME       at_dblog_THBDump
#   NR         46
#   PERIODIC   yes
#   RELATIVE   no
#   REP        -1
#   STATE      Next: 04:00:00
#   TIMESPEC   04:00:00
#   TRIGGERTIME 1671418800
#   TRIGGERTIME_FMT 2022-12-19 04:00:00
#   TYPE       at
#   READINGS:
#     2022-12-18 20:32:48   state           Next: 04:00:00
#
setstate at_dblog_THBDump Next: 04:00:00
setstate at_dblog_THBDump 2022-12-18 20:32:48 state Next: 04:00:00

[/code]


ist das soweit korrekt ? auch das unspezifische "clientside"

Fehlermeldung bekomme ich nicht direkt; weiß aber auch nicht, wohin das backup geschrieben wird.

bitte um Hilfe

lg

Thomas

[DS_Starter]

Hallo Thomas,

das ist ein DbRep-Thema und passt nicht hierher.
Der Aufruf ist erstmal ok, aber mehr ist dazu nicht zu sagen zumal das DbRep-Device nicht dargestellt ist.

Das können wir uns gerne anschauen, aber bitte nicht hier in diesem Thread, sondern in "Sonstiges".
Dort gibt es auch einen DbRep-Thread, oder ein neues Thema öffnen.

LG,
Heiko

[SusisStrolch]

Und wie sieht es bei dir eigentlich mit der V 5.5.6 aus ?

Bin ich leider noch nicht dazu gekommen. Aber ich denke das ich bis morgen etwas dazu sagen kann.

Edit: Ich hatte die 5.5.6 doch schon anscheinend am 17. eingespielt - wußte ich nicht mehr...

[SusisStrolch]

So - Zwischenstand 5.5.6
Meine Synology führt Sa/So einen Hyperbackup aus. Dabei wird MariaDB heruntergefahren.
Als Ergebnis hatte ich einige Cache-Files erhalten. Super!
Was mir sonst so auffiel:
- das importierte Cache-File wird nicht (mehr) umbenannt
- mysql Fehler führen noch immer zum Verlust des MemCache
  Hierbei sind es nicht nur die falschen UTF-8, sondern auch so Dinge wie "cache buffer overflow" auf der DB-Seite
  (der default so um die 16MB groß ist und relativ leicht überschritten werden kann
   wenn es aus techn. Gründen (Backup) mal etwas größere Cache-Files gibt)
- werden zwei Imports (oder zwei aufeinanderfolgende Transaktionen) ausgelöst ohne das die Erste beendet ist
  so werden keine Transaktionen mehr an die DB gesendet - anscheinend wird dann das Ende der ersten Transaktion nicht erkannt.
  Zumindest findet sich im Log wiederkehrend der Eintrag

Code Auswählen Erweitern

4: DbLog logdb - xx of xx events inserted into table history
4: DbLog logdb - commit inserted data table history
4: DbLog logdb - begin transaction

  Cache-Files werden jedoch nach Überschreiten des Limits geschrieben.

[SusisStrolch]

So - Zwischenstand 5.5.6

Nachtrag: im Falle der blockierten Transaktion helfen weder "reopen" noch "exportCache purgeCache".
Der Cache und derMemoryCache werden zwar anscheinend gepurged,

Code Auswählen Erweitern

2022.12.19 19:51:13.716 4: DbLog logdb - MemCache contains 45 entries to process
2022.12.19 19:51:13.716 4: DbLog logdb - DbLogType is: Current/History
2022.12.19 19:51:13.717 5: DbLog logdb - MemCache contains:  1 -> 2022-12-19 19:50:45|ESPEasy_pondctrl_Wasser|ESPEASY|Temperature: 0.7|Temperature|0.7|
2022.12.19 19:51:13.717 5: DbLog logdb - MemCache contains:  2 -> 2022-12-19 19:50:49|EZ.Fenster2|MQTT2_DEVICE|Wifi_Channel: 7|Wifi_Channel|7|
...
2022.12.19 19:51:13.728 5: DbLog logdb - MemCache contains:  45 -> 2022-12-19 19:51:11|EMS_Boiler|MQTT2_DEVICE|outdoorTemp: 8.8|outdoorTemp|8.8|
2022.12.19 19:51:13.869 5: DbLog logdb - DbLogType is: Current/History
2022.12.19 19:51:13.870 4: DbLog logdb - AutoCommit mode: OFF, Transaction mode: ON
2022.12.19 19:51:13.871 4: DbLog logdb - Insert mode: Array
2022.12.19 19:51:13.881 4: DbLog logdb - Primary Key used in history: none
2022.12.19 19:51:13.881 4: DbLog logdb - Primary Key used in current: DEVICE,READING
2022.12.19 19:51:13.882 5: DbLog logdb - processing 1 -> TS: 2022-12-19 19:50:45, Dev: ESPEasy_pondctrl_Wasser, Type: ESPEASY, Event: Temperature: 0.7, Reading: Temperature, Val: 0.7, Unit:
2022.12.19 19:51:13.882 5: DbLog logdb - processing 2 -> TS: 2022-12-19 19:50:49, Dev: EZ.Fenster2, Type: MQTT2_DEVICE, Event: Wifi_Channel: 7, Reading: Wifi_Channel, Val: 7, Unit:
...
2022.12.19 19:51:13.894 5: DbLog logdb - processing 44 -> TS: 2022-12-19 19:51:09, Dev: Verbrauch.Warmwasser, Type: EC3000, Event: power: 318.323207283562, Reading: power, Val: 318.323207283562, Unit:
2022.12.19 19:51:13.894 5: DbLog logdb - processing 45 -> TS: 2022-12-19 19:51:11, Dev: EMS_Boiler, Type: MQTT2_DEVICE, Event: outdoorTemp: 8.8, Reading: outdoorTemp, Val: 8.8, Unit:
2022.12.19 19:51:13.932 4: DbLog logdb - 45 of 45 events inserted into table history
2022.12.19 19:51:14.072 4: DbLog logdb - commit inserted data table history
2022.12.19 19:51:14.076 4: DbLog logdb - begin transaction
2022.12.19 19:51:14.119 4: DbLog logdb - ################################################################
2022.12.19 19:51:14.120 4: DbLog logdb - ###              start of new Logcycle                       ###
2022.12.19 19:51:14.120 4: DbLog logdb - ################################################################


jedoch fährt die nächste Transaktion an die Wand (MemCache war doch nicht leer / commit ist nicht erfolgt):

Code Auswählen Erweitern

2022.12.19 19:51:43.721 4: DbLog logdb - ################################################################
2022.12.19 19:51:43.722 4: DbLog logdb - ###      New database processing cycle - SBP asynchronous    ###
2022.12.19 19:51:43.722 4: DbLog logdb - ################################################################
2022.12.19 19:51:43.724 4: DbLog logdb - MemCache contains 21 entries to process
2022.12.19 19:51:43.724 4: DbLog logdb - DbLogType is: Current/History
2022.12.19 19:51:43.725 5: DbLog logdb - MemCache contains:  46 -> 2022-12-19 19:51:14|WZ.LCG.Environment|LACROSSE|temperature: 19.5|temperature|19.5|
2022.12.19 19:51:43.725 5: DbLog logdb - MemCache contains:  47 -> 2022-12-19 19:51:14|WZ.LCG.Environment|LACROSSE|humidity: 38.100344866095|humidity|38.100344866095|%
...
2022.12.19 19:51:43.730 5: DbLog logdb - MemCache contains:  66 -> 2022-12-19 19:51:39|EMS_Boiler|MQTT2_DEVICE|outdoorTemp: 8.8|outdoorTemp|8.8|
2022.12.19 19:51:43.957 5: DbLog logdb - DbLogType is: Current/History
2022.12.19 19:51:43.958 4: DbLog logdb - AutoCommit mode: OFF, Transaction mode: ON
2022.12.19 19:51:43.958 4: DbLog logdb - Insert mode: Array
2022.12.19 19:51:43.968 4: DbLog logdb - Primary Key used in history: none
2022.12.19 19:51:43.968 4: DbLog logdb - Primary Key used in current: DEVICE,READING
2022.12.19 19:51:43.969 5: DbLog logdb - processing 46 -> TS: 2022-12-19 19:51:14, Dev: WZ.LCG.Environment, Type: LACROSSE, Event: temperature: 19.5, Reading: temperature, Val: 19.5, Unit:
...
2022.12.19 19:51:43.974 5: DbLog logdb - processing 66 -> TS: 2022-12-19 19:51:39, Dev: EMS_Boiler, Type: MQTT2_DEVICE, Event: outdoorTemp: 8.8, Reading: outdoorTemp, Val: 8.8, Unit:
2022.12.19 19:51:43.987 4: DbLog logdb - 21 of 21 events inserted into table history
2022.12.19 19:51:45.344 4: DbLog logdb - commit inserted data table history
2022.12.19 19:51:45.347 4: DbLog logdb - begin transaction

Einzig "shutdown restart" hilft an der Stelle...

[DS_Starter]

Was mir sonst so auffiel:
- das importierte Cache-File wird nicht (mehr) umbenannt

Das hatte ich doch tatsächlich vergessen zu implementieren.
Ist jetzt nachgeholt.

- mysql Fehler führen noch immer zum Verlust des MemCache

Das habe ich nochmal intensiv geprüft und die Fehlerbehandlung verbessert.
Im SQL Fehlerfall werden die Daten an den Cache zurück gegeben wenn ta_on ist (default).
Ausschnitt log:

Code Auswählen Erweitern


2022.12.19 23:22:28.245 4: DbLog LogDB1 - ################################################################
2022.12.19 23:22:28.246 4: DbLog LogDB1 - ###      New database processing cycle - SBP asynchronous    ###
2022.12.19 23:22:28.246 4: DbLog LogDB1 - ################################################################
2022.12.19 23:22:28.247 4: DbLog LogDB1 - MemCache contains 379 entries to process
2022.12.19 23:22:28.247 4: DbLog LogDB1 - DbLogType is: Current/History
2022.12.19 23:22:28.264 4: DbLog LogDB1 - Operation: log_asynch
2022.12.19 23:22:28.265 4: DbLog LogDB1 - AutoCommit: ON, Transaction: ON
2022.12.19 23:22:28.265 4: DbLog LogDB1 - Insert mode: Array
2022.12.19 23:22:28.270 4: DbLog LogDB1 - begin transaction
2022.12.19 23:22:28.335 2: DbLog LogDB1 - Error table fhemtest1.history - DBD::mysql::st execute_array failed: executing 379 generated 37 errors at ./FHEM/93_DbLog.pm line 2932.

2022.12.19 23:22:28.343 4: DbLog LogDB1 - transaction rollback table fhemtest1.history
2022.12.19 23:22:28.344 4: DbLog LogDB1 - Transaction is switched on. Transferred data is returned to the cache.
2022.12.19 23:22:28.344 2: DbLog LogDB1 - WARNING - only 0 of 379 events inserted into table fhemtest1.history
2022.12.19 23:22:28.347 4: DbLog LogDB1 - begin transaction
2022.12.19 23:22:28.421 4: DbLog LogDB1 - 379 of 379 events updated in table fhemtest1.current
2022.12.19 23:22:28.424 4: DbLog LogDB1 - commit inserted data table fhemtest1.current


- werden zwei Imports (oder zwei aufeinanderfolgende Transaktionen) ausgelöst ohne das die Erste beendet ist
  so werden keine Transaktionen mehr an die DB gesendet - anscheinend wird dann das Ende der ersten Transaktion nicht erkannt.

Das konnte nur in einem Fehlerfall vorkommen, habe ich korrigiert.

Nachtrag: im Falle der blockierten Transaktion helfen weder "reopen" noch "exportCache purgeCache".

set ... stopSubProcess  hätte geholfen.
Aber das sollte sich erledigt haben.

Version 5.6.7 liegt im contrib.

LG

[SusisStrolch]

Wow!
Super - werde ich im Laufe des Tages direkt testen!

Edit: ich werde mal versuchen den "set ... stopSubProcess" in meine fhem.service zu dübeln...

[DS_Starter]

Edit: ich werde mal versuchen den "set ... stopSubProcess" in meine fhem.service zu dübeln...

Denke daran dass du den Vorteil des geringen Speicherverbrauchs verlierst wenn du "im Betrieb" den SubProcess neu
startest. Das sollte man nur machen wenn es sein muß (was normalerweise nicht der Fall sein wird).
Deswegen realisieren wir ja den zeitigen fork bei FHEM Start bevor alles fertig geladen ist.

[DS_Starter]

Im Bulk-Insert Mode bringt das Modul im Fehlerfall jetzt detaillierte Informationen des SQL-Problems.
Hier ein Beispiel für "Duplicate entry" wenn ein primary Key gesetzt ist, aber durch das Attr noSupportPK=1 der Support deaktiviert wurde:

Code Auswählen Erweitern


2022.12.20 14:47:40.561 2: DbLog LogDB1 - Error table fhemtest1.history - DBD::mysql::st execute failed: Duplicate entry '2022-12-20 14:47:40-Dum.Energy-T' for key 'PRIMARY' [for Statement "INSERT INTO fhemtest1.history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES ('2022-12-20 14:47:40','Dum.Energy','DUMMY','','T','578.8',''),('2022-12-20 14:47:40','Dum.Energy','DUMMY','','T','578.8',''),('2022-12-20 14:47:40','MySTP_5000','SMAINVERTER','','etotal','50244.169',''),('2022-12-20 14:47:40','MySTP_5000','SMAINVERTER','','etoday','0.865',''),('2022-12-20 14:47:40','MySTP_5000','SMAINVERTER','','total_pac','0.071',''),('2022-12-20 14:47:40','MySTP_5000','SMAINVERTER','','state','0.071','')"] at ./FHEM/93_DbLog.pm line 2741.

2022.12.20 14:47:40.562 2: DbLog LogDB1 - Transaction is switched off. Transferred data is lost.


Transaction: OFF -> Transaction is switched off. Transferred data is lost.