Fehler nach Umstieg auf DBLog, execute_array in 93_DBLog.pm Zeile 3179

[Heiner33]

Hallo zusammen,

habe heute versucht auf DBLog umzusteigen, Datenbank (auf MariaDB Basis) hat auch schon einige Einträge, aber leider bekomme ich direkt nach Start von FHEM auch unzählige Fehlermeldungen im Log:

2023.02.11 21:04:30.753 2: DbLog myDbLog - Error table history - DBD::mysql::st execute_array failed: executing 1336 generated 13 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3179.

2023.02.11 21:04:31.344 2: DbLog myDbLog - Error table history - DBD::mysql::st execute_array failed: executing 1337 generated 13 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3179.

2023.02.11 21:04:32.199 2: DbLog myDbLog - Error table history - DBD::mysql::st execute_array failed: executing 1338 generated 13 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3179.

usw...

Könnt ihr mir helfen, woran das Problem liegt bzw. wie ich es eingrenzen kann?

Danke!

[DS_Starter]

Ein list vom Device wäre hilfreich und ein Auszug des Log mit gesetzten verbose 5 im DbLog-Device.

[Heiner33]

Hier ist ein list des DBLog Devices:

Code Auswählen Erweitern

Internals:
   COLUMNS    field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
   CONFIGURATION /opt/fhem/dbLog.conf
   DEF        /opt/fhem/dbLog.conf .*:.*
   FD         4
   FUUID      63ab5a9e-f33f-48bb-e775-7e4ff6218cdae3d7
   FVERSION   93_DbLog.pm:v5.8.0-s27165/2023-02-01
   MODE       synchronous
   MODEL      MYSQL
   NAME       myDbLog
   NR         2
   NTFY_ORDER 50-myDbLog
   PID        4192
   REGEXP     .*:.*
   SBP_PID    4205
   SBP_STATE  running
   STATE      DBD::mysql::st execute_array failed: executing 20064 generated 91 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3179.

   TYPE       DbLog
   UTF8       1
   dbconn     mysql:database=fhem;host=db;port=3306
   dbuser     fhem
   eventCount 1073
   HELPER:
     COLSET     1
     DEVICECOL  64
     EVENTCOL   512
     LONGRUN_PID 1676178244.88686
     OLDSTATE   DBD::mysql::st execute_array failed: executing 20064 generated 91 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3179.

     PACKAGE    main
     READINGCOL 64
     TC         current
     TH         history
     TYPECOL    64
     UNITCOL    32
     VALUECOL   128
     VERSION    5.8.0
   Helper:
     DBLOG:
       state:
         myDbLog:
           TIME       1676178244.65385
           VALUE      DBD::mysql::st execute_array failed: executing 20064 generated 91 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3179.

   OLDREADINGS:
   READINGS:
     2023-02-12 06:04:04   CacheUsage      2
     2023-02-12 06:04:04   state           DBD::mysql::st execute_array failed: executing 20064 generated 91 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3179.

Attributes:

Wenn ich Verbose auf 5 setze werde ich im Logfile erschlagen. Dementsprechend schwierig ist es eine relevante Stelle für das Problem zu finden. Zwischendrin sehe ich die folgenden Meldungen:

...
2023.02.12 06:07:22.629 5: DbLog myDbLog - processing 512 -> TS: 2023-02-12 06:07:22, Dev: FritzBox, Type: FRITZBOX, Event: state: Didn't get a session ID, Reading: state, Val: Didn't get a session ID, Unit:
2023.02.12 06:07:22.629 5: DbLog myDbLog - processing 513 -> TS: 2023-02-12 06:07:22, Dev: FritzBox, Type: FRITZBOX, Event: guestWlan: 0, Reading: guestWlan, Val: 0, Unit:
2023.02.12 06:07:22.629 4: DbLog myDbLog - begin Transaction
2023.02.12 06:07:22.755 2: DbLog myDbLog - Error table history - DBD::mysql::st execute_array failed: executing 335 generated 13 errors [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)"] at ./FHEM/93_DbLog.pm line 3179.

2023.02.12 06:07:22.756 4: DbLog myDbLog - Transaction is switched on. Transferred data is returned to the cache.
2023.02.12 06:07:22.764 4: DbLog myDbLog - Transaction rollback table >history<
2023.02.12 06:07:22.765 5: DbLog myDbLog - row back to Cache: 179 -> 2023-02-12 06:07:20|Cal_Termine|CALENDAR|calname: FHEM_Termine|calname|FHEM_Termine|
2023.02.12 06:07:22.766 5: DbLog myDbLog - row back to Cache: 180 -> 2023-02-12 06:07:20|Cal_Termine|CALENDAR|lastUpdate: 2023-02-12 06:07:18|lastUpdate|2023-02-12 06:07:18|
...

Falls mit "Executing 335" das zur gelistete "Processing Element" gemeint ist, wäre das dieses hier:

Code Auswählen Erweitern

2023.02.12 06:07:22.594 5: DbLog myDbLog - processing 335 -> TS: 2023-02-12 06:07:20, Dev: CalView_Termine, Type: CALVIEW, Event: t_010_bdate: 27.07.2023, Reading: t_010_bdate, Val: 27.07.2023, Unit:

[DS_Starter]

Leider sieht man die benutzten Attribute nicht im List.
Versuche es bitte mit folgenden Attr:

Code Auswählen Erweitern


insertMode   = 1
commitMode = basic_ta:off


Damit sollte im Log eindeutiger zu lesen sein bei welchen Daten der Fehler auftritt.
Wenn klar geworden ist, welche Daten das Problem verursachen, kann man weiter an einer Lösung arbeiten.

Vermutlich würde das Attr useCharfilter = 1 das Problem unterdrücken.

[Heiner33]

Bisher waren keine Attribute gesetzt, daher nichts im List.

Habe die zwei genannten Attribute gesetzt und FHEM neu gestartet. Es erscheinen einige Meldungen im Logfile, soweit keine Fehler. Irgendwann landet nichts mehr im Logfile und der State meines DBLog Devices zeigt "Another operation is in progress. Data is stored temporarily.". Dann steigt die Anzahl der Einträge im "CacheUsage" aber das war's dann erst mal.

edit:
Ein Neustart später, dann diese Meldung im Logfile

2023.02.12 10:09:24.187 2: DbLog myDbLog - ERROR table history - DBD::mysql::st execute failed: Incorrect string value: '\xF0\x9F\x8E\x82Ge...' for column `fhem`.`history`.`EVENT` at row 1 [for Statement "INSERT INTO history (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (?,?,?,?,?,?,?)" with ParamValues: 0='2023-02-12 10:09:19', 1='CalView_Termine', 2='CALVIEW', 3='t_003_summary: �...Geburtstag Andi', 4='t_003_summary', 5='�...Geburtstag Andi', 6=undef] at ./FHEM/93_DbLog.pm line 2885.

Könnte was mit dem Sonderzeichen (🎂) zu tun haben? utf8 Parameter steht auf 1 in der dbconfig, configcheck liefert:

Result of encoding check

Encoding used by Client (connection): UTF8MB3
Encoding used by DB fhem: UTF8MB4

PS: Vielen Dank schon mal so weit für deine Unterstützung!!

Grüße

[DS_Starter]

Könnte was mit dem Sonderzeichen (🎂) zu tun haben?

Ja, deswegen sollte dir Attr useCharfilter = 1 helfen.

Das Attr insertMode, commitMode   kannst du wieder löschen.

Danach FHEM wieder restarten.

[Heiner33]

Das useCharfilter = 1 hilft, keine weiteren Fehler mehr.

Frage dazu: Verliere ich mit dem gesetzten Attribut nicht die Möglichkeit generell UTF-8 Zeichen auch im DBLog zu haben?
Ist das nicht eher als Workaround zu betrachten und ich müsste die Connection irgendwie auf UTF8MB4 umstellen oder wird das generell von DBLog nicht supported?

Danke und Grüße

[DS_Starter]

Frage dazu: Verliere ich mit dem gesetzten Attribut nicht die Möglichkeit generell UTF-8 Zeichen auch im DBLog zu haben?
Ist das nicht eher als Workaround zu betrachten und ich müsste die Connection irgendwie auf UTF8MB4 umstellen oder wird das generell von DBLog nicht supported?

Es ist ein Workaround um schnell zu helfen. Es ist nun die Frage ob man solche Daten, die 4 Byte Zeichen erfordern, überhaupt loggen sollte. D.h. ob man die braucht.
MariaDB UTF8 kann 1, 2 oder 3 Byte Zeichen verarbeiten soviel ich weiß, wohingegen UTF8MB4 mit 4 Byte arbeiten kann.

Du kannst die Connection testweise auf UTF8MB4 umstellen indem du in DbLog die Zeile 2605 austauscht:

alt

Code Auswählen Erweitern


($err, undef) = _DbLog_SBP_dbhDo ($name, $dbh, 'set names "UTF8"', $subprocess);


neu

Code Auswählen Erweitern


($err, undef) = _DbLog_SBP_dbhDo ($name, $dbh, 'set names "utf8mb4"', $subprocess);


Danach restarten.

Bin mir allerdings unsicher ob es konform mit dem DBD-Treiber (DbLog setzt darauf auf) ist, denn in dessen Doku ist beschrieben:

...
Do not try to change network charset (e.g. via SQL command SET NAMES manually) to anything different then UTF-8 as it would confuse underlying C library and DBD::MariaDB would misbehave (e.g. would lead to broken/insecure quote method or an emulated client side placeholders replacement).
...

Aber probieren kannst du es ja.

[DS_Starter]

Ich habe eine meiner Datenbanken auch mal auf UTF8MB4 umgestellt und DbLog so ergänzt, dass sich das Connection set automatisch auf das database utf8 character set einstellt.
Bisher habe ich keine negativen Seiteneffekte feststellen können.

Du kannst die adaptierte DbLog Version aus meinem Contrib (Fußtext) ziehen, FHEM restarten und testen.

[Heiner33]

Hallo,

wow, vielen Dank. Habe mir das aktualisierte Modul geholt und konnte es erfolgreich testen, das Sonderzeichen landet in der Datenbank!

Sofern mit der adaptierten DbLog Version keine weiteren Probleme auftreten sollten, wird diese Version dann in Zukunft als Update "offiziell" verteilt oder müsste ich die Version immer aus dem Contrib holen?

[DS_Starter]

Sehr schön. 

Diese Änderung würde ich in das nächste Check-In mit übernehmen. Das wird wahrscheinlich so gegen dem kommenden WE sein.
Vielleicht testet der eine oder andere Mitleser noch; immerhin haben mehr als 360 User den Thread angeschaut; die bereitgestellte Version.
Sollten doch noch problematische Seiteneffekte auftreten, würde ich mir ein Attribut überlegen um dieses Feature für die User anbieten zu können.

Edit: Kannst du bitte den Output von "set ... configCheck" posten ? Interessiert mich mal.

LG,
Heiko

[DS_Starter]

Ich habe die Erläuterungen in der Commandref für DbLog um einen Absatz zu utf8(mb4) ergänzt:

....
  Die Standardinstallation der MySQL/MariaDB Datenbank sieht die Nutzung der Collation utf8_bin vor.
  Mit dieser Einstellung können Zeichen bis 3 Byte Länge gespeichert werden was im Allgemeinen ausreichend ist.
  Sollen jedoch Zeichen mit 4 Byte Länge (z.B. Emojis) in der Datenbank gespeichert werden, ist der Zeichensatz
  utf8mb4 zu verwenden.
  Dementsprechend wäre in diesem Fall die MySQL/MariaDB Datenbank mit folgendem Statement anzulegen:
 
        CREATE DATABASE `fhem` DEFAULT CHARACTER SET utf8mb4 COLLATE utf8mb4_bin;
 
  In Konfigurationsfile (siehe unten) ist die utf8-Unterstützung mit dem Schlüssel utf8 => 1 einzuschalten sofern utf8
  genutzt werden soll.
....

[Heiner33]

Danke für die Infos und die schnelle Lösung des Problems!
Der configCheck liefert das Ergebnis bzgl. charset:

Result of encoding check

Encoding used by Client (connection): UTF8MB4_GENERAL_CI
Encoding used by DB fhem: UTF8MB4_GENERAL_CI
Rating:
Recommendation: settings o.k.

PS: Ich habe eine MariaDB via Docker aufgesetzt - keine besonderen Einstellungen vorgenommen, da scheint die Standard-Collation wohl schon auf utf8mb4 zu stehen. Ich hatte das zumindest nicht bewusst umgestellt oder die Datenbank speziell angelegt.

[DS_Starter]

Danke.
Ich denke die Beispiel-Scripte im contrib zur Anlage einer neuen DB für DbLog stellen ich auch auf die Benutzung von utf8mb4 anstatt wie aktuell utf8 um. Dann erspart man sich den Ärger falls man Datensätze loggen will die solche Sonderzeichen enthalten.
Weiß nicht genau ab welcher MySQL Version utf8mb4 eingeführt wurde, aber wer jetzt beginnt kann mit Sicherheit auf utf8mb4  setzen.

[betateilchen]

Weiß nicht genau ab welcher MySQL Version utf8mb4 eingeführt wurde,

Die bessere Frage wäre "wann wurde utf8mb4 die Standardeinstellung"
Antwort: bis 5.7 war utf8 die Standardeinstellung, alles was danach kommt, hat utf8mb4 als default.