Neues Database Plugin

[Sisamiwe]

Aber ich meine in der Logging.yaml kannst Du das ergänzen

Danke. Test läuft

[bmx]

Eigentlich ist Msinn der Experte für Logging. Aber ich meine in der Logging.yaml kannst Du das ergänzen:

loggers:
    #...
    lib.db:
        level: DEBUG
​

Der Handler wird dann automatisch von lib genommen. Alternativ kannst Du einen eigenen Handler aufnehmen:

handlers:
    # ...
    shng_db_lib_file:
        class: logging.handlers.TimedRotatingFileHandler
        formatter: shng_detail
        level: DEBUG
        utc: false
        when: midnight
        backupCount: 7
        filename: ./var/log/lib_db.log
        encoding: utf8

und den dann eintragen.

[Sisamiwe]

Hallo,

kann man das Log der lib.db auch auf Debug setzen?

Heute Nachmittag gab es diese Meldeung:

2023-09-29  16:10:48 ERROR    lib.db                                   Can not execute query: SELECT 1 (args OrderedDict()): Packet sequence number wrong - got 1 expected 2
2023-09-29  16:10:48 WARNING  lib.db                                   Database [Database]: Connection error Packet sequence number wrong - got 1 expected 2
2023-09-29  16:10:48 WARNING  lib.db                                   fetchone: No cursor defined for stmt SELECT 1 with params ()​

[bmx]

Du kannst dir die Formatter aus der logging.yaml.default mal anschauen. Also shng_detail zum Beispiel sollte die Zeilennummern liefern.

[Sisamiwe]

Daher gerne mit Zeilennummern

Hast Du zufällig dafür eine Vorlage?

[bmx]

Ok, aber es kann durchaus sein, das

2023-09-29 03:20:23 ERROR plugins.database _query Database: Error for query SELECT id, name, time, val_str, val_num, val_bool, changed from item WHERE name = heizung.kessel.abgastemperatur;: Packet sequence number wrong - got 1 expected 2
​

seine Ursache woanders hat und irreführend ist. Daher gerne mit Zeilennummern, dann kann man gezielter suchen.

[Sisamiwe]

Warum hat das Ding angeblich keine ID Nummer?

In der Tabelle 'item' ist das aber enthalten:

(371,'heizung.kessel.abgastemperatur',1695968216635,NULL,34.2,1,1695968221561)

[bmx]

Ich denke nicht das es vom remove_odler_than_maxage her kommt. Ich denke eher hier

2023-09-29 03:20:23 ERROR plugins.database _query Database: Error for query SELECT id, name, time, val_str, val_num, val_bool, changed from item WHERE name = heizung.kessel.abgastemperatur;: Packet sequence number wrong - got 1 expected 2
2023-09-29 03:20:23 WARNING plugins.database id id(): No id found for item heizung.kessel.abgastemperatur - Exception Packet sequence number wrong - got 1 expected 2
2023-09-29 03:20:23 ERROR plugins.database _query Database: Error for query SELECT MAX(id) FROM item;: (0, '')
2023-09-29 03:20:23 WARNING plugins.database _dump Problem dumping heizung.kessel.abgastemperatur: (0, '')
2023-09-29 03:20:23 WARNING plugins.database _dump Error rolling back: (0, '')
​

liegt der Hase im Pfeffer. Ändere doch mal den Formatter für das Debug los so das Du Zeilennummern vom Code mit dargestellt bekommst. So ist das etwas schwierig.
Und ich würde mir mal das Item heizung.kessel.abgastemperatur ansehen. Warum hat das Ding angeblich keine ID Nummer?

[Sisamiwe]

Hallo,

heute nach ist der Fehler wieder aufgetreten und ich habe hier mal den Debug-Log Auszug dazu:

2023-09-29  03:18:24 DEBUG    plugins.database             _query                 Database: Fetch INSERT INTO log(item_id, time, val_str, val_num, val_bool, duration, changed) VALUES (1134,1695950275911,None,4.6,1,None,1695950304484);: 1
2023-09-29  03:18:24 DEBUG    plugins.database             _query                 Database: Fetch UPDATE item SET time = 1695950275911, val_str = None, val_num = 4.6, val_bool = 1, changed = 1695950304484 WHERE id = 1134;: 1
2023-09-29  03:18:24 DEBUG    plugins.database             _dump                  Dump completed
2023-09-29  03:19:17 DEBUG    plugins.database             _query                 Database: Fetch SELECT id, name, time, val_str, val_num, val_bool, changed from item WHERE name = steckdosen.ug.waschkueche.waschmaschine.stromwert;: (301, 'steckdosen.ug.waschkueche.waschmaschine.stromwert', 1695950303760, None, 0.0, 0, 1695950304072)
2023-09-29  03:19:24 DEBUG    plugins.database             _dump                  Starting dump
2023-09-29  03:20:22 DEBUG    plugins.database             _query                 Database: Fetch SELECT count(*) FROM log WHERE item_id = 301 AND time >= 1678662000000;: ((9887472,),)
2023-09-29  03:20:22 DEBUG    plugins.database             _query                 Database: Fetch SELECT id, name, time, val_str, val_num, val_bool, changed from item WHERE name = env.host_rpi.temperature;: (976, 'env.host_rpi.temperature', 1695950187190, None, 62.3, 1, 1695950244610)
2023-09-29  03:20:22 DEBUG    plugins.database             _dump                  Dumping env.host_rpi.temperature/976 with 2 values
2023-09-29  03:20:22 DEBUG    plugins.database             _query                 Database: Fetch SELECT time, item_id, duration, val_str, val_num, val_bool, changed FROM log WHERE item_id = 976 AND time = 1695950187190;: ((1695950187190, 976, None, None, 62.3, 1, 1695950244610),)
2023-09-29  03:20:22 DEBUG    plugins.database             _query                 Database: Fetch UPDATE log SET duration = 120682, val_str = None, val_num = 62.3, val_bool = 1, changed = 1695950422248 WHERE item_id = 976 AND time = 1695950187190;: 1
2023-09-29  03:20:22 DEBUG    plugins.database             _query                 Database: Fetch SELECT time, item_id, duration, val_str, val_num, val_bool, changed FROM log WHERE item_id = 976 AND time = 1695950307872;: ()
2023-09-29  03:20:22 DEBUG    plugins.database             _query                 Database: Fetch INSERT INTO log(item_id, time, val_str, val_num, val_bool, duration, changed) VALUES (976,1695950307872,None,64.2,1,None,1695950422248);: 1
2023-09-29  03:20:22 DEBUG    plugins.database             _query                 Database: Fetch UPDATE item SET time = 1695950307872, val_str = None, val_num = 64.2, val_bool = 1, changed = 1695950422248 WHERE id = 976;: 1
2023-09-29  03:20:22 DEBUG    plugins.database             _query                 Database: Fetch SELECT count(*) FROM log WHERE item_id = 301 AND time <= 1678662000000;: ((74866,),)
2023-09-29  03:20:22 DEBUG    plugins.database             remove_older_than_maxage remove_older_: steckdosen.ug.waschkueche.waschmaschine.stromwert remove older than 13.03.2023 - 00:00 - 74.866 records to delete
2023-09-29  03:20:23 DEBUG    plugins.database             _query                 Database: Fetch DELETE FROM log WHERE item_id = 301 ORDER BY time ASC LIMIT 20000;: 20000
2023-09-29  03:20:23 INFO     plugins.database             remove_older_than_maxage remove_older_: steckdosen.ug.waschkueche.waschmaschine.stromwert deleted 20.000 of 74.866 log entries - took 0.61 seconds, averaging 0.0030 seconds per 100 entries
2023-09-29  03:20:23 ERROR    plugins.database             _query                 Database: Error for query SELECT id, name, time, val_str, val_num, val_bool, changed from item WHERE name = heizung.kessel.abgastemperatur;: Packet sequence number wrong - got 1 expected 2
2023-09-29  03:20:23 WARNING  plugins.database             id                     id(): No id found for item heizung.kessel.abgastemperatur - Exception Packet sequence number wrong - got 1 expected 2
2023-09-29  03:20:23 ERROR    plugins.database             _query                 Database: Error for query SELECT MAX(id) FROM item;: (0, '')
2023-09-29  03:20:23 WARNING  plugins.database             _dump                  Problem dumping heizung.kessel.abgastemperatur: (0, '')
2023-09-29  03:20:23 WARNING  plugins.database             _dump                  Error rolling back: (0, '')
2023-09-29  03:20:23 DEBUG    plugins.database             _initialize_db         DEBUG: delta 3540.219331264496
2023-09-29  03:20:49 WARNING  plugins.database             remove_older_than_maxage remove_older_than_maxage skipped because db is not connected
2023-09-29  03:21:25 NOTICE   plugins.database             notice                 Skipping dump, since an other database operation running! Data is buffered and dumped later.
2023-09-29  03:22:21 WARNING  plugins.database             remove_older_than_maxage remove_older_than_maxage skipped because db is not connected
2023-09-29  03:22:25 NOTICE   plugins.database             notice                 Skipping dump, since an other database operation running! Data is buffered and dumped later.
2023-09-29  03:22:27 DEBUG    plugins.database             stop                   Stop method called​

Hilft das bzw. wem sagt das was?
Scheinbar kommt das Theme von "remove_older_than_maxage", oder?

[Sisamiwe]

a) SmarthomeNG Neustart?

Neustart von shNG löst das Problem machmal für Tage, machmal nur für 1-2 Stunden. Habe mir jetzt erstmal eine Logik gebaut, die das Log überwacht und einen Neustart triggert.

Kannst Du sobald der Fehler auftritt nochmal das Loglevel erhöhen und hier posten?

Hab das Log entsprechend geändert und stelle das Ergebnis hier ein.

Nutzt Du MySQL?

Ja, richtig.

Das ist bei normaler Plugin Nutzung kein Problem, kann bei Nutzung von Funktionen des Plugins jedoch zu Problemen führen

Ich nutzte keine Funktionen des Plugins. bzw. ist die Darstellung von Serien in der Visu auch über die Plugin-Funktion gelöst?

[Msinn]

Exception Packet sequence number wrong

Nutzt Du MySQL? MySQL unterstützt je Session nur einen aktiven Cursor. Das ist bei normaler Plugin Nutzung kein Problem, kann bei Nutzung von Funktionen des Plugins jedoch zu Problemen führen, da dann zur gleichen Zeit zwei Curors aktiv sein können.

[aschwith]

Wie kommst Du aus diesem DB Fehler raus?

a) SmarthomeNG Neustart?
b) DB Neustart?

Kannst Du sobald der Fehler auftritt nochmal das Loglevel erhöhen und hier posten?

[Sisamiwe]

Hallo,

ich habe ein Problem mit dem database-Plugin und hoffe auf Eure Hilfe.

In unregelmäßigen Abständen (alle 2-3 Tage, manchmal auch mehrfach am Tag) tritt ein solcher Fehler auf.
Hier mal der Verlauf von heute:

Erste Fehlermeldung:

2023-09-25  00:26:27 ERROR    lib.db                                   Can not execute query: SELECT id, name, time, val_str, val_num, val_bool, changed from item WHERE name = %(id)s; (args OrderedDict([('id', 'steckdosen.ug.waschkueche.waschmaschine.stromwert')])): Packet sequence number wrong - got 1 expected 2
2023-09-25  00:26:27 ERROR    plugins.database                         Database: Error for query SELECT id, name, time, val_str, val_num, val_bool, changed from item WHERE name = steckdosen.ug.waschkueche.waschmaschine.stromwert;: Packet sequence number wrong - got 1 expected 2
2023-09-25  00:26:27 WARNING  plugins.database                         id(): No id found for item steckdosen.ug.waschkueche.waschmaschine.stromwert - Exception Packet sequence number wrong - got 1 expected 2
2023-09-25  00:26:27 ERROR    lib.db                                   Can not execute query: SELECT MAX(id) FROM item; (args OrderedDict()): (0, '')
2023-09-25  00:26:27 ERROR    plugins.database                         Database: Error for query SELECT MAX(id) FROM item;: (0, '')
2023-09-25  00:26:27 WARNING  plugins.database                         Problem dumping steckdosen.ug.waschkueche.waschmaschine.stromwert: (0, '')
2023-09-25  00:26:27 WARNING  plugins.database                         Error rolling back: (0, '')
2023-09-25  00:26:27 ERROR    lib.db                                   Can not execute query: SELECT 1 (args OrderedDict()): (0, '')
2023-09-25  00:26:27 WARNING  lib.db                                   Database [Database]: Connection error (0, '')
2023-09-25  00:26:27 WARNING  lib.db                                   fetchone: No cursor defined for stmt SELECT 1 with params ()​

und dann fortlaufend:

2023-09-25  00:27:43 WARNING  plugins.database                         remove_older_than_maxage skipped because db is not connected
2023-09-25  00:29:15 WARNING  plugins.database                         remove_older_than_maxage skipped because db is not connected​

Die Datenbank ist nicht mehr verbunden und es werden somit auch keine Werte mehr geschrieben.

Der Fehlermeldungen vom 22.09:
Erste Fehlermeldung:

2023-09-22 04:07:12 ERROR lib.db Can not execute query: SELECT 1 (args OrderedDict()): Packet sequence number wrong - got 1 expected 2
2023-09-22 04:07:12 WARNING lib.db Database [Database]: Connection error Packet sequence number wrong - got 1 expected 2
2023-09-22 04:07:12 WARNING lib.db fetchone: No cursor defined for stmt SELECT 1 with params ()
2023-09-22 04:07:15 NOTICE plugins.database Skipping dump, since an other database operation running! Data is buffered and dumped later.​​

dann

2023-09-22 18:19:24 ERROR lib.db Can not execute query: SELECT 1 (args OrderedDict()): Packet sequence number wrong - got 1 expected 2
2023-09-22 18:19:24 WARNING lib.db Database [Database]: Connection error Packet sequence number wrong - got 1 expected 2
2023-09-22 18:19:24 WARNING lib.db fetchone: No cursor defined for stmt SELECT 1 with params ()
2023-09-22 18:19:43 NOTICE plugins.database Skipping dump, since an other database operation running! Data is buffered and dumped later.
2023-09-22 18:19:49 NOTICE plugins.database Dumping buffered data from skipped dump(s).
2023-09-22 18:19:58 WARNING plugins.avm fritzbox_7530@: Setting AVM Device defined in Item=avm.smarthome.hkr_og_bad.target_temperature with avm_data_type=target_temperature to value=7.0 FAILED!
2023-09-22 18:20:00 WARNING plugins.db_addon no valid data from database query received during _prepare_value_list. Aborting...
2023-09-22 18:21:53 ERROR lib.db Can not execute query: SELECT 1 (args OrderedDict()): Packet sequence number wrong - got 1 expected 2
2023-09-22 18:21:53 WARNING lib.db Database [Database]: Connection error Packet sequence number wrong - got 1 expected 2
2023-09-22 18:21:53 ERROR lib.db Can not execute query: SELECT 1 (args OrderedDict()): (0, '')
2023-09-22 18:21:53 WARNING lib.db Database [Database]: Connection error (0, '')
2023-09-22 18:24:14 WARNING plugins.db_addon no valid data from database query received during _prepare_value_list. Aborting...
2023-09-22 18:24:15 ERROR lib.db Can not execute query: DELETE FROM log WHERE item_id = %(id)s ORDER BY time ASC LIMIT %(maxrecords)s; (args OrderedDict([('id', 301), ('maxrecords', 20000)])): 'NoneType' object has no attribute 'read'
2023-09-22 18:24:15 ERROR lib.db Can not execute query: SELECT id, name, time, val_str, val_num, val_bool, changed from item WHERE name = %(id)s; (args OrderedDict([('id', 'wetter.froggit.pressure.pressure_abs')])): Packet sequence number wrong - got 102 expected 3
2023-09-22 18:24:15 ERROR plugins.database Database: Error for query DELETE FROM log WHERE item_id = 301 ORDER BY time ASC LIMIT 20000;: 'NoneType' object has no attribute 'read'
2023-09-22 18:24:15 ERROR plugins.database Database: Error for query SELECT id, name, time, val_str, val_num, val_bool, changed from item WHERE name = wetter.froggit.pressure.pressure_abs;: Packet sequence number wrong - got 102 expected 3
2023-09-22 18:24:15 ERROR lib.scheduler.tasks Method plugins.database.Remove old exception: 'NoneType' object has no attribute 'read'
Traceback (most recent call last):
File "/usr/local/smarthome/lib/scheduler.py", line 707, in _task
obj()
File "/usr/local/smarthome/plugins/database/__init__.py", line 1595, in remove_older_than_maxage
self._execute(self._prepare("DELETE FROM {log} WHERE item_id = :id ORDER BY time ASC LIMIT :maxrecords;"), {'id': item_id, 'maxrecords': self.max_delete_logentries}, cur=cur)
File "/usr/local/smarthome/plugins/database/__init__.py", line 1727, in _execute
self._query(self._db.execute, query, params, cur)
File "/usr/local/smarthome/plugins/database/__init__.py", line 1757, in _query
raise e
File "/usr/local/smarthome/plugins/database/__init__.py", line 1754, in _query
tuples = func(self._prepare(query), params, cur=cur)
File "/usr/local/smarthome/lib/db.py", line 332, in execute
result = cur.execute(stmt, args)
File "/home/smarthome/.local/lib/python3.9/site-packages/pymysql/cursors.py", line 158, in execute
result = self._query(query)
File "/home/smarthome/.local/lib/python3.9/site-packages/pymysql/cursors.py", line 325, in _query
conn.query(q)
File "/home/smarthome/.local/lib/python3.9/site-packages/pymysql/connections.py", line 549, in query
self._affected_rows = self._read_query_result(unbuffered=unbuffered)
File "/home/smarthome/.local/lib/python3.9/site-packages/pymysql/connections.py", line 779, in _read_query_result
result.read()
File "/home/smarthome/.local/lib/python3.9/site-packages/pymysql/connections.py", line 1164, in read
self._read_result_packet(first_packet)
File "/home/smarthome/.local/lib/python3.9/site-packages/pymysql/connections.py", line 1239, in _read_result_packet
self._get_descriptions()
File "/home/smarthome/.local/lib/python3.9/site-packages/pymysql/connections.py", line 1311, in _get_descriptions
field = self.connection._read_packet(FieldDescriptorPacket)
File "/home/smarthome/.local/lib/python3.9/site-packages/pymysql/connections.py", line 715, in _read_packet
recv_data = self._read_bytes(bytes_to_read)
File "/home/smarthome/.local/lib/python3.9/site-packages/pymysql/connections.py", line 736, in _read_bytes
data = self._rfile.read(num_bytes)
AttributeError: 'NoneType' object has no attribute 'read'
2023-09-22 18:24:15 WARNING plugins.database id(): No id found for item wetter.froggit.pressure.pressure_abs - Exception Packet sequence number wrong - got 102 expected 3
2023-09-22 18:24:15 ERROR lib.db Can not execute query: SELECT MAX(id) FROM item; (args OrderedDict()): (0, '')
2023-09-22 18:24:15 ERROR plugins.database Database: Error for query SELECT MAX(id) FROM item;: (0, '')
2023-09-22 18:24:15 WARNING plugins.database Problem dumping wetter.froggit.pressure.pressure_abs: (0, '')
2023-09-22 18:24:15 WARNING plugins.database Error rolling back: (0, '')
2023-09-22 18:24:15 ERROR lib.db Can not execute query: SELECT 1 (args OrderedDict()): (0, '')
2023-09-22 18:24:15 WARNING lib.db Database [Database]: Connection error (0, '')​​

und dann wieder fortlaufend:

2023-09-22 19:22:22 ERROR lib.db Can not execute query: SELECT id, name, time, val_str, val_num, val_bool, changed from item WHERE name = %(id)s; (args OrderedDict([('id', 'heizung.kessel.kesseltemperatur_ist')])): Packet sequence number wrong - got 1 expected 2
2023-09-22 19:22:22 ERROR plugins.database Database: Error for query SELECT id, name, time, val_str, val_num, val_bool, changed from item WHERE name = heizung.kessel.kesseltemperatur_ist;: Packet sequence number wrong - got 1 expected 2
2023-09-22 19:22:22 WARNING plugins.database id(): No id found for item heizung.kessel.kesseltemperatur_ist - Exception Packet sequence number wrong - got 1 expected 2
2023-09-22 19:22:22 ERROR lib.db Can not execute query: SELECT MAX(id) FROM item; (args OrderedDict()): (0, '')
2023-09-22 19:22:22 ERROR plugins.database Database: Error for query SELECT MAX(id) FROM item;: (0, '')
2023-09-22 19:22:22 WARNING plugins.database Problem dumping heizung.kessel.kesseltemperatur_ist: (0, '')
2023-09-22 19:22:22 WARNING plugins.database Error rolling back: (0, '')
2023-09-22 19:22:22 ERROR lib.db Can not execute query: SELECT 1 (args OrderedDict()): (0, '')
2023-09-22 19:22:22 WARNING lib.db Database [Database]: Connection error (0, '')
2023-09-22 19:22:22 WARNING lib.db fetchone: No cursor defined for stmt SELECT 1 with params ()
2023-09-22 19:23:33 WARNING plugins.database remove_older_than_maxage skipped because db is not connected
2023-09-22 19:24:22 NOTICE plugins.database Skipping dump, since an other database operation running! Data is buffered and dumped later.​​

Der shNG Core ist das aktuelle develop.
Der database Plugin ist 1.6.11
Ich nutze eine mysql bzw. mariadb.

Kann jemand was zu dem Fehler sagen?
Wenn das Plugin merkt, dass die DB nicht verbunden ist, warum erfolgt kein reconnect?

Danke Euch.

[Msinn]

Normalerweise lesen hier mehr mit als auf github. Du kannst aber trotzdem einen Issue auf github aufmachen (im Plugins Repo), dann geht das nicht verloren.

[lexxmm]

Soll ich das mal über github melden oder lesen die Jungs hier mit?