db-Abfrage ist manchmal "NoneType"

[henfri]

Hallo,

ich habe seit längerem unregelmäßig diese Warnung im Log:

2014-02-07 20:33:25 WARNING  Allgemein.Stromzaehler.Momentanleistung_1min Item Allgemein.Stromzaehler.Momentanleistung_1min: problem evaluating (sh.Allgemein.Stromzaehler.Zaehlerstand()- sh.Allgemein.Stromzaehler.Zaehlerstand.db('max', '1i', '1i'))*60.0*1000.0: unsupported operand type(s) for -: 'float' and 'NoneType'
2014-02-07 21:00:01 WARNING  wunderground Item Wetter.Niederschlag_Heute: value  does not match type num. Via Logic None
2014-02-07 21:00:58 WARNING  Allgemein.Stromzaehler.Leistungsdurchschni24h Item Allgemein.Stromzaehler.Leistungsdurchschni24h: problem evaluating (sh.Allgemein.Stromzaehler.Zaehlerstand()-sh.Allgemein.Stromzaehler.Zaehlerstand.db('max', '1d', '1d'))/24*1000: unsupported operand type(s) for -: 'float' and 'NoneType'

Komisch ist dabei, dass dieses Problem sehr sporadisch auftritt -auch in der git-Version mit den aktuellen Verbesserungen im sqlite-Plugin.

Z.B. um:

2014-02-07 00:17:00
2014-02-07 00:20:17
2014-02-07 01:05:44
2014-02-07 02:20:55
2014-02-07 03:02:16
2014-02-07 03:02:16
...
2014-02-07 03:29:27
2014-02-07 04:14:09
2014-02-07 05:05:42
2014-02-07 10:52:51
2014-02-07 13:10:37
2014-02-07 13:14:52
2014-02-07 14:46:29
2014-02-07 15:25:55
2014-02-07 15:31:09
2014-02-07 15:46:56
2014-02-07 16:02:34
2014-02-07 16:39:09
2014-02-07 18:59:06
2014-02-07 19:33:24
2014-02-07 19:42:48
2014-02-07 20:33:25
2014-02-07 21:00:58

Vor 3:29 Uhr kam die Fehlermeldung mehrmals pro Minute.
Ein Debug-Log hängt an.
Hier noch die Items:

[Allgemein]
    [[Stromzaehler]]
    sv_page=Strom
    name = Strom
    visu=yes
	[[[Counter]]]
	    name = Counter
	    type = num
	    cache=yes
	    sqlite = yes
	    knx_dpt = 12
	    enforce_updates=yes
	    knx_send = 6/7/0
	    knx_listen = 6/7/0
	[[[Zaehlerstand]]]
	    name = Zaehlerstand
	    type = num
	    sqlite = yes
	    knx_dpt = 14
	    #knx_send = 6/7/1
	    eval = sh.Allgemein.Stromzaehler.Counter()/800.0
	    eval_trigger = Allgemein.Stromzaehler.Counter
    	    sv_widget={{ plot.period('p99872', 'item', 'avg', '2h',0,'','','','','','area') }}
    	    visu=yes
    [[[Momentanleistung_1min]]]
	    name = Momentanleistung_1min
	    type = num
	    sqlite = yes
	    knx_dpt = 14
	    #knx_send = 6/7/2
	    eval = (sh.Allgemein.Stromzaehler.Zaehlerstand()- sh.Allgemein.Stromzaehler.Zaehlerstand.db('max', '1i', '1i'))*60.0*1000.0
	    eval_trigger=Allgemein.Stromzaehler.Counter
    	    sv_widget={{ plot.period('p998dd71', 'item', 'avg', '2h', 0, 0,4000, ''    , '', '','area') }}
	    visu=yes
        [[[Momentanleistung_10min]]]
	    name = Momentanleistung_10min
	    type = num
	    sqlite = yes
	    knx_dpt = 14
	    knx_send = 6/7/2
	    eval = (sh.Allgemein.Stromzaehler.Zaehlerstand()- sh.Allgemein.Stromzaehler.Zaehlerstand.db('max', '11i', '10i'))*60.0*1000.0/10.0
	    eval_trigger=Allgemein.Stromzaehler.Counter
    	    sv_widget={{ plot.period('p99871', 'item', 'avg', '2h',0,0,4000, ''    , '', '','area') }}
    	    visu=yes
        [[[Momentanleistung_freq]]]
	    name = Momentanleistung_freq
	    type = num
	    sqlite = yes
	    knx_dpt = 14
	    knx_send = 6/7/3
#Frequenzzähler: Jeder Counter=1/800kWh=3600/800kws=3600/800*1000Ws; Zeit zwischen zwei Impulsen messen und dadurch teilen --> W
	    eval = 4500/sh.Allgemein.Stromzaehler.Counter.prev_age()
	    eval_trigger=Allgemein.Stromzaehler.Counter
	    enforce_updates=yes
    	    sv_widget={{ plot.period('p998dsd71', 'item', 'avg', '2h',0,0,4000, ''    , '', '','area') }}
	    visu=yes
        [[[Leistungsdurchschni24h]]]
	    name = Last
	    type = num
	    sqlite = yes
	    knx_dpt = 14
	    eval = (sh.Allgemein.Stromzaehler.Zaehlerstand()-sh.Allgemein.Stromzaehler.Zaehlerstand.db('max', '1d', '1d'))/24*1000
	    eval_trigger=Allgemein.Stromzaehler.Counter
    	visu=yes        
		[[[Leistung_Haustechnik]]]
		type=num
		sqlite=yes
		knx_dpt=9
		knx_cache=6/7/10
		[[[Verbrauch_Haustechnik]]]
		type=num
		sqlite=yes
		eval=value+sh.Allgemein.Stromzaehler.Leistung_Haustechnik()*sh.Allgemein.Stromzaehler.Leistung_Haustechnik.prev_age()/60.0/60.0
		eval_trigger=Allgemein.Stromzaehler.Leistung_Haustechnik

Hast du eine Idee, woran das liegen kann?

Gruß,
Hendrik

[callidomus]

Hi Hendrik,

die Last auf Deinem System ist zu hoch. Die geht ja bis zu 4.5!
Irgendetwas auf Deinem System frisst die Ressourcen.

Wenn das Plugin nicht innerhalb von ein zwei Sekunden eine Antwort bekommt, dann gibt es None zurück.

Ich denke das System ist überlastet.

Bis bald

Marcus

[henfri]

Ok, das hilft. Danke!

Gesendet von meinem LT26i mit Tapatalk

[henfri]

Hallo,

ich habe die Last jetzt deutlich unter 1 (ich hatte ein Problem mit dem Dateisystem). Trotzdem habe ich das Problem weiterhin. Hast du noch eine weitere Idee?

Oder sollte ich versuchen mal eine Warnung im Falle eines Timeout einzubauen?

Gruß,
Hendrik

[callidomus]

Hi Hendrik,

so spontan fällt mir nichts ein. Eine LogMeldung kannst Du in Zeile 383 des SQLite Plugins hinzufügen.

Vllt. hilft auch ein aktualisiertes Log.

Bis bald

Marcus

[henfri]

Danke. Wird gemacht. Melde mich.

Gesendet von meinem LT26i mit Tapatalk

[henfri]

Hallo Marcus,

die Zeile 383 wir -nach meinem Verständnis- ausgeführt, wenn nix aus der Datenbank zurück kam, oder?

        tuples = self._fetchall(query)
        if tuples is None:
            return

Hier könnte ich ja nur ein Debug 'Rückgabe ist leer' zurück geben.

Müsste ich nicht eher hier einsteigen:

    def _fetchall(self, *query):
        if not self._fdb_lock.acquire(timeout=2):
            return
            logger.Warning('timeout in fetchall')
        try:

Und dann könnte man ja auch noch die aktuelle Load mit ausgeben (das hattest du doch in sh.py eingebaut... Ich finde es aber nicht in der Doku).

Gruß,
Hendrik

[henfri]

Hallo Marcus,

ich denke, ich bin ein Stück weiter. Ich hatte bisher das Log immer nur nach sql durchsucht. Wenn ich aber nicht case-sensitiv suche, komme ich weiter:

2014-03-08 21:01:06,581 DEBUG    Main         SQLite 3.7.9 -- __init__.py:__init__:60
2014-03-08 21:01:06,581 DEBUG    Main         SQLite: database integrity ok -- __init__.py:__init__:77
2014-03-08 21:01:06,582 DEBUG    Main         SQLite Maintain next time: 2014-03-09 03:02:00+01:00 -- scheduler.py:_next_time:301
2014-03-08 21:01:06,620 DEBUG    Main         Item og.Till.heizung.ist = 20.2 via SQLite None None -- item.py:set:466
2014-03-08 21:01:06,628 DEBUG    Main         Item og.Lina.heizung.ist = 21.1 via SQLite None None -- item.py:set:466
2014-03-08 21:01:06,648 DEBUG    Main         Item og.Kinderbad.heizung.ist = 20.8 via SQLite None None -- item.py:set:466
2014-03-08 21:01:06,698 DEBUG    Main         Item Allgemein.Stromzaehler.Counter = 605805.0 via SQLite None None -- item.py:set:466
2014-03-08 21:01:06,699 DEBUG    Main         Item Allgemein.Stromzaehler.Zaehlerstand = 757.255 via SQLite None None -- item.py:set:466
2014-03-08 21:01:06,699 DEBUG    Main         Item Allgemein.Stromzaehler.Momentanleistung_1min = 450.00000000300133 via SQLite None None -- item.py:set:466
2014-03-08 21:01:06,700 DEBUG    Main         Item Allgemein.Stromzaehler.Momentanleistung_freq = 12139.81833436297 via SQLite None None -- item.py:set:466
2014-03-08 21:01:06,722 DEBUG    Main         Item Wetter.Windgeschwindigkeit.Wetterstation = 0.07 via SQLite None None -- item.py:set:466
2014-03-08 21:01:06,758 DEBUG    Main         Starting sql Plugin -- plugin.py:start:67
2014-03-08 21:01:52,052 WARNING  Main         SQLite: Problem with '("SELECT ROUND(SUM(_avg * _dur) / SUM(_dur)), 2) from num WHERE _item='Allgemein.Stromzaehler.Zaehlerstand' AND _start + _dur > 1394222511726 AND _start <= 1394222511726",)': near ")": syntax error -- __init__.py:_fetchall:224
2014-03-08 21:01:57,626 WARNING  Main         SQLite: Problem with '("SELECT ROUND(SUM(_avg * _dur) / SUM(_dur)), 2) from num WHERE _item='Allgemein.Stromzaehler.Zaehlerstand' AND _start + _dur > 1393444917002 AND _start <= 1394222517002",)': near ")": syntax error -- __init__.py:_fetchall:224
2014-03-08 21:02:04,712 WARNING  Main         SQLite: Problem with '("SELECT ROUND(SUM(_avg * _dur) / SUM(_dur)), 2) from num WHERE _item='Allgemein.Stromzaehler.Zaehlerstand' AND _start + _dur > 1393444924712 AND _start <= 1394308924712",)': near ")": syntax error -- __init__.py:_fetchall:224
2014-03-08 21:03:37,123 WARNING  Main         SQLite: Problem with '("SELECT ROUND(SUM(_avg * _dur) / SUM(_dur)), 2) from num WHERE _item='Allgemein.Stromzaehler.Zaehlerstand' AND _start + _dur > 1394308956742 AND _start <= 1394309016742",)': near ")": syntax error -- __init__.py:_fetchall:224
2014-03-08 21:03:47,712 WARNING  Main         SQLite: Problem with '("SELECT ROUND(SUM(_avg * _dur) / SUM(_dur)), 2) from num WHERE _item='Allgemein.Stromzaehler.Zaehlerstand' AND _start + _dur > 1394308967712 AND _start <= 1394309027712",)': near ")": syntax error -- __init__.py:_fetchall:224
2014-03-08 22:32:03,234 WARNING  Main         SQLite: Problem with '("SELECT ROUND(SUM(_avg * _dur) / SUM(_dur)), 2) from num WHERE _item='Allgemein.Stromzaehler.Zaehlerstand' AND _start + _dur > 1394314263234 AND _start <= 1394314323234",)': near ")": syntax error -- __init__.py:_fetchall:224

Ich denke, das grenzt den Fehler gut ein?
Ich habe die db auch mal weg-geschoben, so dass eine neue erzeugt wird --> keine Änderung. An der Kommandozeile (-i) waren alle meine Versuche, der DB etwas zu entlocken (unterschiedliche Items) nicht erfolgreich.

Anbei das ganze Log.

Gruß,
Hendrik

[callidomus]

Hallo Hendrik,

danke für den qualifizierten Input.

Ich habe den aufgezeigten Bug gefixt. Ist in develop.

Bis bald

Marcus

[henfri]

Klasse, danke.
Wird getestet.


Gesendet von unterwegs

[henfri]

Hallo,

gute Nachricht: Vorher kamen ja sekundenweise Fehlermeldungen. Die sind jetzt weg.
Aber eine neue Fehlermeldung habe ich:

2014-03-09 09:25:16,097 ERROR    Allgemein.Stromzaehler.Momentanleistung_10min Item Allgemein.Stromzaehler.Momentanleistung_10min: problem running <bound method SQL.update_item of <plugins.sqlite.SQL object at 0x2121390>>: list index out of range -- item.py:__update:371
  File "/usr/local/smarthome/plugins/sqlite/__init__.py", line 182, in update_item
  File "/usr/local/smarthome/plugins/sqlite/__init__.py", line 265, in _insert

Anbei das ganze log.
Die db lade ich gleich zu DropBox hoch --> https://dl.dropboxusercontent.com/u/...arthome_db.zip (12MB).

Gruß,
Hendrik



Gruß,
Hendrik

[callidomus]

Hi Hendrik,

in dem angehängten Log ist der Fehler aber nicht zu finden, oder bin ich zu blind?

Ich sehe mir das jetzt aber mal im Code an.

Bis bald

Marcus

[callidomus]

Hi,

ok, ich konnte gedanklich einen Fehler nachvollziehen und im Code fixen.

Findet sich in develop.

Bis bald

Marcus

[henfri]

Danke!
Teste...

Gesendet von meinem LT26i mit Tapatalk

[henfri]

Hallo Marcus,

kannst du etwas zu dem Fehler sagen?
Weshalb ich frage:
Meine Root-Platte ist vor zwei Wochen über den Jordan gegangen -die hohe Load war vielleicht ein Symptom. Ich habe das letzte Backup (juhuu!) auf deinen USB-Stick gepackt und warte gerade auf die Lieferung einer (zwei) Ersatz-SSD. Ich glaube, das führ auch zu einer hohen load, falls der Stick die Daten nicht schnell genug liefern kann (zumindest habe ich weiterhin eine Load um 0.8, aber nicht mehr >>2)

Aber: Seit dem Rückspielen des Backups hatte ich mehrmals das Problem das die Visualisierung nicht mehr aktualisiert wurde und auch dass auf Events auf dem KNX-Bus nicht reagiert wurde (auch wenn im Bus-Monitor von sh.py (also dem Log)) der Vorgang registriert wurde.

Dieses Problem ist seit dem Update auf Develop weg.
Macht das Sinn?

Mein eigentliches Problem:

2014-03-11 19:40:45 WARNING Allgemein.Stromzaehler.Leistungsdurchschni24h Item Allgemein.Stromzaehler.Leistungsdurchschni24h: problem evaluating (sh.Allgemein.Stromzaehler.Zaehlerstand()-sh.Allgemein.Stromzaehler.Zaehlerstand.db('max', '1d', '1d'))/24*1000: unsupported operand type(s) for -: 'float' and 'NoneType'

besteht aber weiterhin (load=0.6) -auch im obigen Log.

Hast du da noch eine Idee?

Gruß,
Hendrik