[Gelöst] DBLog SQLite Problem: st execute_array failed

Begonnen von Elektrofreak, 08 März 2017, 09:35:05

Vorheriges Thema - Nächstes Thema

Elektrofreak

Hallo,

ich bekomme seit dem Update auf FHEM 5.8 folgende Fehlermeldung in Plots:

ZitatDBD::SQLite::st execute_array failed: executing 35024 generated 183 errors at ./FHEM/93_DbLog.pm line 1581. , 0

Ich habe die Vermutung, dass irgendetwas im LogDB oder eher im SVG-Modul nicht richtig klappt. Wenn ich mir den Cache vom DBLog-Modul ansehe (läuft mit SQLite), dann sehe ich Einträge von Devices, die ich beim entprechenden SVG-Plot beim Klick auf "show preprocessed inputs" nicht sehe. Selbst nach einem Commit cache (nachdem die Daten in der Datenbank gespeichert sein sollten) zeigt der SVG-Plot nichts an.

Einige Plots bleiben komplett leer, andere zeigen ein paar Werte an (wobei es mir vor kommt, als ob da Punkte fehlen...)

Was ich komisch finde:
Das LogDB-Modul zeigt in den Readings keine Fehler an. Gleiches ist beim SVG-Plot. Allerdings steht unter:

Probably associated with
Zitatsys_logdb DBD::SQLite::st execute_array failed: executing 35024 generated 183 errors at ./FHEM/93_DbLog.pm line 1581. , 0 DbLog

Liegt das mit dem Update auf FHEM 5.8 zusammen oder ist meine Datenbank defekt?  :-[ Vielleicht habe ich es auch durch ein schlechtes "reduceLog" zerschossen  :(

Edit: Ich bekomme das Problem auch bei einer frisch angelegten Datenbank  :'(

PS: Falls das hier das falsche Unterforum ist, bitte verschieben  ::)


Elektrofreak

#1
Hallo,

leider bekomme ich immer noch das Problem.

Was ich bisher probiert habe:
- alte Datenbank nach wiki-Eintrag reparieren
- neue Datenbank anlegen
- Dateirechte für fhem kontrolliert
- fhem update und apt-get update/upgrade

Ich kann reproduzieren, dass die Datenbank beim Befehl "count" folgenden Fehler erzeugt:

ZitatDBD::SQLite::st execute_array failed: unable to open database file [err was 14 now 2000000000] executing 246 generated 246 errors at ./FHEM/93_DbLog.pm line 1581. , 0

Ich habe das Gefühl, dass es noch an dem update auf fhem 5.8 sondern an dem aktuellen dbLog Modul liegt, welches jetzt nicht-blockierende Befehle besitzt.

Es müsste dann doch noch jemand das Problem haben...  :(

Elektrofreak

Wie so oft sitzt das Problem vor dem Rechner  ::)

Nachdem ich verschiedene Versionen aus dem fhem-SVN herunter geladen habe und immer das selbe Problem auftrat, konnte ich die Module als Problemquellen ausschließen.

Es waren wohl die Benutzerrechte für die Dateien richtig, jedoch nicht für den db-Ordner. Daher hatte das Modul keine Schreibrechte.

Bond246

Ich würde mich gerne in diesen alten Thread nochmal einklinken.

Bei mir funktioniert die Datenbank-Anbindung mit dem gleichen Fehler heute aus heiterem Himmel nicht mehr.
2018.10.09 09:47:56 2: DbLog Logdb -> Error table history - DBD::mysql::st execute_array failed: executing 28 generated 3 errors at ./FHEM/93_DbLog.pm line 2060.

Zu der Zeit war ich gar nicht im Haus. Anhand der Plots kann man sehen, dass bis dahin alles funktioniert hat.
Ich hab auch keine Updates eingespielt oder sonstige Änderungen am System durchgeführt - zumindest nicht bewusst.

FHEM loggt bei mir in eine Mariadb10, die auf meiner Synology läuft. Vor gut 2 Wochen habe ich da das Temp-Verzeichnis neu gemappt, damit das Log-Reduce wieder funktioniert (https://forum.fhem.de/index.php/topic,87447.msg838954.html#msg838954). Das hat aber einwandfrei funktioniert. Ich sehe keinen objektiven Grund, warum jetzt plötzlich dieser Fehler auftritt.

Der FHEM Server läuft auf einem RaspberryPi mit raspbian und FHEM ist in Version 5.9 auf dem letzten Stand.
Nachdem der Fehler heute anftrat, habe ich sowohl die Synology als auch den RaspberryPi rebootet und FHEM nochmal geupdated. Leider ohne Erfolg.

Weiß jemand, was der Fehler überhaupt heißt?

Beste Grüße,
Bond

DS_Starter

Hallo Bond,

führe im DbLog bitte ein "set ... configCheck" aus und poste bitte das komplette Ergebnis.
Und dann bitte noch ein List deines DbLog-Devices.
Ich vermute ein Konfigurationsproblem was nichts mit dem Modul oder FHEM zu tun hat.

Grüße
Heiko
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

Bond246

#5
configCheck:
Result of DbLog version check

Used DbLog version: 3.12.2
Recommendation: Your running version may be the current one. Please check for updates of DbLog periodically.

Result of configuration read check

Connection parameter store type: file
Connection parameter: Connection -> mysql:database=fhem;host=diskstation;port=3307, User -> fhemuser, Password -> read o.k.

Result of connection check

Connection to database fhem successfully done.
Recommendation: settings o.k.

Result of encoding check

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

Result of logmode check

Logmode of DbLog-device Logdb is: asynchronous
Recommendation: settings o.k.

Result of shutdown sequence preparation check

Attribute "shutdownWait" is set to: 2
Recommendation: The setting may be ok. But due to the Reading "background_processing_time" is not available (you may set attribute "showproctime"), the current
setting is only a rough estimate.


Result of plot generation method check

WEB: plotfork=1
WEBphone: plotfork=1
WEBtablet: plotfork=1
Recommendation: settings o.k.

Result of table 'history' check

Column width set in DB fhem.history: 'DEVICE' = 64, 'TYPE' = 64, 'EVENT' = 512, 'READING' = 64, 'VALUE' = 128, 'UNIT' = 32
Column width used by Logdb: 'DEVICE' = 64, 'TYPE' = 64, 'EVENT' = 512, 'READING' = 64, 'VALUE' = 128, 'UNIT' = 32
Recommendation: settings o.k.

Result of table 'current' check

Column width set in DB fhem.current: 'DEVICE' = 64, 'TYPE' = 64, 'EVENT' = 512, 'READING' = 64, 'VALUE' = 128, 'UNIT' = 32
Column width used by Logdb: 'DEVICE' = 64, 'TYPE' = 64, 'EVENT' = 512, 'READING' = 64, 'VALUE' = 128, 'UNIT' = 32
Recommendation: settings o.k.

Result of check 'Search_Idx' availability

Index 'Search_Idx' exists and contains recommended fields 'DEVICE', 'READING', 'TIMESTAMP'.
Recommendation: settings o.k.

Result of check 'Report_Idx' availability for DbRep-devices

At least one DbRep-device assigned to Logdb is used, but the recommended index 'Report_Idx' is missing.
Recommendation: You can create the index by executing statement 'CREATE INDEX Report_Idx ON `history` (TIMESTAMP, READING) USING BTREE;'
Depending on your database size this command may running a long time.
Please make sure the device 'Logdb' is operating in asynchronous mode to avoid FHEM from blocking when creating the index.
Note: If you have just created another index which covers the same fields and order as suggested (e.g. a primary key) you don't need to create the 'Report_Idx' as well !


Was meinst du mit Liste des DbLog Devices?
Hier erstmal die config:
define Logdb DbLog ./db.conf .*:.*
attr Logdb DbLogExclude .*
attr Logdb DbLogSelectionMode Exclude/Include
attr Logdb DbLogType Current/History
attr Logdb asyncMode 1
attr Logdb room Logs
attr Logdb shutdownWait 2
attr Logdb verbose 5


verbose 5 hab ich vorhin aktiviert, um eventuell mehr Infos zu bekommen. Dem ist aber nicht so.

Hier noch die Internals:
COLUMNS      field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
CONFIGURATION      ./db.conf
DEF                        ./db.conf .*:.*
MODE                      asynchronous
MODEL                    MYSQL
NAME                      Logdb
NR                          17
NTFY_ORDER          50-Logdb
PID                         2202
REGEXP                  .*:.*
STATE                     DBD::mysql::st execute_array failed: executing 1625 generated 139 errors at ./FHEM/93_DbLog.pm line 2063.
TYPE                       DbLog
UTF8                      1
VERSION                3.12.2
dbconn                   mysql:database=fhem;host=diskstation;port=3307
dbuser                    fhemuser

Frank_Huber



Zitat von: Bond246 am 09 Oktober 2018, 22:26:08
Was meinst du mit Liste des DbLog Devices?

Fhem Befehl: list Logdb

Gesendet von meinem Doogee S60 mit Tapatalk


DS_Starter

Sieht erstmal sehr gut aus.
Also die Mitteilung der DB "executing 1625 generated 139 errors" besagt i.A. dass 1625 Datensätze weggeschrieben werden sollen und 139 nicht geschrieben werden können. Diese Sätze verhindern den gesamten Vorgang weil es als Transaktion ausgeführt wird.

Setze mal bitte das Attribut:


commitMode = basic_ta:off


Wie sieht es dann aus ? Und poste mal die Ausgabe von "set ... listCache" (mit gesetztem Attribut).
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

Bond246

Hi,
super dass ihr mir hier so flott helft :-)

Hier nochmal die Device-List
Internals:
   COLUMNS    field length used for Device: 64, Type: 64, Event: 512, Reading: 64, Value: 128, Unit: 32
   CONFIGURATION ./db.conf
   DEF        ./db.conf .*:.*
   MODE       asynchronous
   MODEL      MYSQL
   NAME       Logdb
   NR         17
   NTFY_ORDER 50-Logdb
   PID        2202
   REGEXP     .*:.*
   STATE      DBD::mysql::st execute_array failed: executing 2113 generated 185 errors at ./FHEM/93_DbLog.pm line 2063.

   TYPE       DbLog
   UTF8       1
   VERSION    3.12.2
   dbconn     mysql:database=fhem;host=diskstation;port=3307
   dbuser     fhemuser
   HELPER:
     COLSET     1
     DEVICECOL  64
     EVENTCOL   512
     LASTLIMITRUNTIME 1539117967.56464
     OLDSTATE   DBD::mysql::st execute_array failed: executing 2113 generated 185 errors at ./FHEM/93_DbLog.pm line 2063.

     READINGCOL 64
     TYPECOL    64
     UNITCOL    32
     VALUECOL   128
   READINGS:
     2018-10-09 22:47:07   CacheUsage      2121
     2018-10-09 22:47:08   NextSync        2018-10-09 22:47:38 or if CacheUsage 500 reached
     2018-10-09 03:01:29   reduceLogState  reduceLogNbl finished. Rows processed: 263276, deleted: 26853, updated: 556, time: 89.00sec
     2018-10-09 22:47:08   state           DBD::mysql::st execute_array failed: executing 2113 generated 185 errors at ./FHEM/93_DbLog.pm line 2063.

   cache:
     index      314506
Attributes:
   DbLogExclude .*
   DbLogSelectionMode Exclude/Include
   DbLogType  Current/History
   asyncMode  1
   room       Logs
   shutdownWait 2
   verbose    5


Und der listCache Output ist ziemlich lang, deswegen als txt-File im Anhang.

Bond246

Es sieht ziemlich danach aus, dass es jetzt mit commitMode = basic_ta:off wieder läuft.
Die Synology ist stark am arbeiten und fhem reagiert ziemlich langsam wenn ich das Logfile öffne.
Vermutlich wird das logfile gerade immens groß, weil ich verbose noch auf 5 hab.

DS_Starter

Ja, dann stelle erstmal das verbose wieder auf 3 oder 2. Ich schaue mir dein File gerade an.
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

Ich glaube ich habe die Ursache gefunden. Es sind Datensätze vorhanden die Steuerzeichen enthalten die wahrscheinlich die DB stören:


325224 => 2018-10-09 22:48:12|Thermostat.WZ1|MAX|desiredTemperature: 10.0|desiredTemperature|10.0|�C
325225 => 2018-10-09 22:48:12|Thermostat.WZ1|MAX|valveposition: 0|valveposition|0|%
325226 => 2018-10-09 22:48:12|Thermostate|STRUCTURE|state: undefined|state|undefined|
325227 => 2018-10-09 22:48:12|Thermostate.WZ|STRUCTURE|state: 10.0 °C|state|10.0 °C|
325228 => 2018-10-09 22:48:12|Thermostate|STRUCTURE|state: undefined|state|undefined|
325229 => 2018-10-09 22:48:12|Thermostate.WZ|STRUCTURE|state: 10.0 °C|state|10.0 °C|


Die Thermostate in STRUCTURE haben als Einheit °C, aber die MAX �C.

Du kannst jetzt so vorgehen:

1. setzte das Attribut useCharfilter = 1
2. führe einen Cacheexport mit Purge aus:  set ... exportCache purgecache

Wenn das geklappt hat schauen wir weiter.
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

Bond246

Es sieht so aus, dass jetzt erstmal Ruhe ist.
Keine weiteren Fehlermeldungen. Die letzte war vor einer halben Stunde. Ungefähr seit dem ich das Charfilter Attribut gesetzt habe und der Cacheexport aktiv ist.

Im listCache sehe ich zwar noch die Steuerzeichen aber vermutlich werden die dann erst bei der Übertragung gefiltert?

45228 => 2018-10-09 23:47:19|Thermostat.Bad|MAX|desiredTemperature: 30.0|desiredTemperature|30.0|�C
45229 => 2018-10-09 23:47:19|Thermostat.Bad|MAX|temperature: 23.3|temperature|23.3|�C
45230 => 2018-10-09 23:47:19|Thermostat.Bad|MAX|valveposition: 91|valveposition|91|%
45231 => 2018-10-09 23:47:19|Thermostate|STRUCTURE|state: undefined|state|undefined|
45232 => 2018-10-09 23:47:19|Thermostate|STRUCTURE|state: undefined|state|undefined|
45233 => 2018-10-09 23:47:19|Thermostat.WZ2|MAX|mode: manual|mode|manual|


Wenn es jetzt wirklich die Steuerzeichen waren, wundert mich aber trotzdem etwas, dass ihm das so plötzlich auf die Füße fällt.
Und dann kann man ja auch eigentlich noch sagen, dass in dem speziellen Fall die Einheit zu der Temperatur halbwegs unwichtig ist, da ich die Einheiten nirgends verwende.

DS_Starter

Naja es war jetzt eine Vermutung von mir. Möglicherweise haben die sich auch als nicht druckbare Zeichen versteckt.
Aber wir sind noch nicht ganz fertig.  ;)

Das Charfilter Attribut lässt du am besten erstmal gesetzt. Das schützt in solchen Fällen.

Der Cache müßte sich jetzt wieder ordentlich leeren, richtig ?
Jetzt kannst du das exportierte Cachefile wieder importieren mit "set ... importCachefile".
Du bekommst eine Drop-Down Liste angezeigt mit dem exportfile. Das importierst du einfach. Dann sind deine Daten nicht verloren.
Wenn meine Vermutung richtig war, sollte der Import jetzt problemlos laufen weil störende Steuerzeichen mit dem Attr rausgefiltert werden.

Die Zeichen �C können auch nur US7ASCII sein, wurdert mich aber trotzdem.

Mach das erstmal. Dann können wir nochmal darüber nachdenken wieso das nun plötzlich aufgetreten 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

Bond246

Also nachdem das ja gestern lief, ging ich davon aus, dass erstmal alles in Ordnung ist.
Weil mich die ständig ratternden Festplatten der Synology genervt haben (was so nicht üblich ist), hab ich das commitMode Attribut wieder entfernt.

Danach war Ruhe.
Was mir jetzt nach der Arbeit aber erst auffiel ist, dass es ohne commitMode=basic_ta:off nicht funktioniert.

Also wieder aktiviert und dann hat er jetzt erstmal alle Cache Einträge wieder übertragen. Deswegen würde ich jetzt mal vaga behaupten, am Charfilter lag es nicht. Aber vermutlich seid ihr da die besseren Experten.