93_DbLog - Umstellung Log-Funktion auf non-blocking

[DS_Starter]

Hallo firesenjung,

momentan dauert es ca. 4-5 Minuten. Die Fehlermeldungen haben sich auf 1-2 pro Nacht reduziert, manchmal sehe ich gar keine Fehler.

Speziell für die Backup-Situation ist im Modul das Feature "set ... reopen X" eingebaut. Wenn du X auf 600 Sekunden setzt, wird die Verbindung zur DB geschlossen und erst nach 10 Minuten wieder aktiviert. Während dieser Zeit kannst du bequem ein konsistetes Backup machen.

Grüße
Heiko

[Tobias]

Hi Heiko,
kann es sein das gar keine Einträge mehr in der Tabelle Current landen? irgendwie hören die bei mir am 06.01.17 auf   

Weiterhin scheint es irgendein Problem mit einem DBLog Aufruf direkt aus 98_Text2Speech.pm zu geben

Code Auswählen Erweitern

# den letzten Value von "Usage" ermitteln um dann die Statistik um 1 zu erhoehen.
  my @LastValue = DbLog_Get($defs{$DbLogDev}, "", "current", "array", "-", "-", $hash->{NAME} ."|". $file.":Usage");
  my $NewValue = 1;
  $NewValue = $LastValue[0]{value} + 1 if($LastValue[0]);

  #           DbLogHash,        DbLogTable, TIMESTAMP, DEVICE,                    TYPE,          EVENT, READING, VALUE,     UNIT
  DbLog_Push($defs{$DbLogDev}, "Current", TimeNow(), $hash->{NAME} ."|". $file, $hash->{TYPE}, $text, "Usage", $NewValue, "");
Beschrieben hier: https://forum.fhem.de/index.php?topic=66354.new;topicseen#new
Muss ich etwas im Aufruf ändern?

[Sunny]

Hallo Heiko,

entschuldige, das ich mich jetzt erst wieder melde. Bin gerade gesundheitlich angeschlagen.

Mit der Version "93_DbLog_V2.11.3.pm" sind die Ansichten mit "async=0" etwas besser aber mit "async=1" deutlich schlechter.
Habe aber nicht viel getestet.

Logfile, habe ich Dir per PM geschickt.

mit "grippalen" Grüßen
sunny

[ioT4db]

Hallo firesenjung,

Speziell für die Backup-Situation ist im Modul das Feature "set ... reopen X" eingebaut. Wenn du X auf 600 Sekunden setzt, wird die Verbindung zur DB geschlossen und erst nach 10 Minuten wieder aktiviert. Während dieser Zeit kannst du bequem ein konsistetes Backup machen.

Grüße
Heiko

Hallo Heiko,
bedeutet also es gilt immer nur je 1x nach dem set-Kommando und ich aktivier es immer vor dem Backup mittels at oder doif. richtig?
probier ich gleich aus.

VG

[DS_Starter]

Hallo Tobias,

kann es sein das gar keine Einträge mehr in der Tabelle Current landen? irgendwie hören die bei mir am 06.01.17 auf

Nein, kann nicht sein. Sie werden mit Attr DbLogType = "Current/Hostory" geschrieben. Mach die mal verbose 5 an und schau ins Log nach irgendwelchen Fehlern beim Insert. Wenn alles sauber läuft sieht es so aus:

Code Auswählen Erweitern


2017.02.06 18:21:04.087 5: DbLog LogDB -> ################################################################
2017.02.06 18:21:04.087 5: DbLog LogDB -> ###              New database processing cycle               ###
2017.02.06 18:21:04.087 5: DbLog LogDB -> ################################################################
2017.02.06 18:21:04.087 5: DbLog LogDB -> MemCache contains 13 entries to process
2017.02.06 18:21:04.087 5: DbLog LogDB -> MemCache contains: 2017-02-06 18:21:00|SMA_Energymeter|SMAEM|Bezug_WirkP_Zaehler_Diff: 0.0066|Bezug_WirkP_Zaehler_Diff|0.0066|
2017.02.06 18:21:04.087 5: DbLog LogDB -> MemCache contains: 2017-02-06 18:21:00|SMA_Energymeter|SMAEM|Bezug_WirkP_Kosten_Diff: 0.0014|Bezug_WirkP_Kosten_Diff|0.0014|
2017.02.06 18:21:04.087 5: DbLog LogDB -> MemCache contains: 2017-02-06 18:21:00|SMA_Energymeter|SMAEM|Einspeisung_WirkP_Zaehler_Diff: 0|Einspeisung_WirkP_Zaehler_Diff|0|
2017.02.06 18:21:04.087 5: DbLog LogDB -> MemCache contains: 2017-02-06 18:21:00|SMA_Energymeter|SMAEM|Einspeisung_WirkP_Verguet_Diff: 0.0000|Einspeisung_WirkP_Verguet_Diff|0.0000|
2017.02.06 18:21:04.087 5: DbLog LogDB -> MemCache contains: 2017-02-06 18:21:00|SMA_Energymeter|SMAEM|-392.3|state|-392.3|
2017.02.06 18:21:04.087 5: DbLog LogDB -> MemCache contains: 2017-02-06 18:21:00|SMA_Energymeter|SMAEM|Saldo_Wirkleistung: -392.3|Saldo_Wirkleistung|-392.3|
2017.02.06 18:21:04.087 5: DbLog LogDB -> MemCache contains: 2017-02-06 18:21:00|SMA_Energymeter|SMAEM|Bezug_Wirkleistung: 392.3|Bezug_Wirkleistung|392.3|
2017.02.06 18:21:04.088 5: DbLog LogDB -> MemCache contains: 2017-02-06 18:21:00|SMA_Energymeter|SMAEM|Bezug_Wirkleistung_Zaehler: 1665.0452|Bezug_Wirkleistung_Zaehler|1665.0452|
2017.02.06 18:21:04.088 5: DbLog LogDB -> MemCache contains: 2017-02-06 18:21:00|SMA_Energymeter|SMAEM|Einspeisung_Wirkleistung: 0.0|Einspeisung_Wirkleistung|0.0|
2017.02.06 18:21:04.088 5: DbLog LogDB -> MemCache contains: 2017-02-06 18:21:00|SMA_Energymeter|SMAEM|Einspeisung_Wirkleistung_Zaehler: 1718.8621|Einspeisung_Wirkleistung_Zaehler|1718.8621|
2017.02.06 18:21:04.088 5: DbLog LogDB -> MemCache contains: 2017-02-06 18:21:01|MySTP_5000|SMAINVERTER|etotal: 13003.739|etotal|13003.739|
2017.02.06 18:21:04.088 5: DbLog LogDB -> MemCache contains: 2017-02-06 18:21:01|MySTP_5000|SMAINVERTER|0.000|state|0.000|
2017.02.06 18:21:04.088 5: DbLog LogDB -> MemCache contains: 2017-02-06 18:21:01|Dum.Energy|DUMMY|TotalConsumption: 392.3|TotalConsumption|392.3|
2017.02.06 18:21:04.096 5: DbLog LogDB -> DbLog_PushAsync called with timeout: 3600
2017.02.06 18:21:04.100 4: DbLog LogDB -> Device: LogDB excluded from database logging due to attribute "excludeDevs" restrictions
2017.02.06 18:21:04.101 5: DbLog LogDB -> Start DbLog_PushAsync
2017.02.06 18:21:04.156 5: DbLog LogDB -> Primary Key used in fhemtest.history: TIMESTAMP DEVICE READING
2017.02.06 18:21:04.156 5: DbLog LogDB -> Primary Key used in fhemtest.current: none
2017.02.06 18:21:04.157 5: DbLog LogDB -> processing event Timestamp: 2017-02-06 18:21:00, Device: SMA_Energymeter, Type: SMAEM, Event: Bezug_WirkP_Zaehler_Diff: 0.0066, Reading: Bezug_WirkP_Zaehler_Diff, Value: 0.0066, Unit:
2017.02.06 18:21:04.157 5: DbLog LogDB -> processing event Timestamp: 2017-02-06 18:21:00, Device: SMA_Energymeter, Type: SMAEM, Event: Bezug_WirkP_Kosten_Diff: 0.0014, Reading: Bezug_WirkP_Kosten_Diff, Value: 0.0014, Unit:
2017.02.06 18:21:04.157 5: DbLog LogDB -> processing event Timestamp: 2017-02-06 18:21:00, Device: SMA_Energymeter, Type: SMAEM, Event: Einspeisung_WirkP_Zaehler_Diff: 0, Reading: Einspeisung_WirkP_Zaehler_Diff, Value: 0, Unit:
2017.02.06 18:21:04.157 5: DbLog LogDB -> processing event Timestamp: 2017-02-06 18:21:00, Device: SMA_Energymeter, Type: SMAEM, Event: Einspeisung_WirkP_Verguet_Diff: 0.0000, Reading: Einspeisung_WirkP_Verguet_Diff, Value: 0.0000, Unit:
2017.02.06 18:21:04.157 5: DbLog LogDB -> processing event Timestamp: 2017-02-06 18:21:00, Device: SMA_Energymeter, Type: SMAEM, Event: -392.3, Reading: state, Value: -392.3, Unit:
2017.02.06 18:21:04.158 5: DbLog LogDB -> processing event Timestamp: 2017-02-06 18:21:00, Device: SMA_Energymeter, Type: SMAEM, Event: Saldo_Wirkleistung: -392.3, Reading: Saldo_Wirkleistung, Value: -392.3, Unit:
2017.02.06 18:21:04.158 5: DbLog LogDB -> processing event Timestamp: 2017-02-06 18:21:00, Device: SMA_Energymeter, Type: SMAEM, Event: Bezug_Wirkleistung: 392.3, Reading: Bezug_Wirkleistung, Value: 392.3, Unit:
2017.02.06 18:21:04.158 5: DbLog LogDB -> processing event Timestamp: 2017-02-06 18:21:00, Device: SMA_Energymeter, Type: SMAEM, Event: Bezug_Wirkleistung_Zaehler: 1665.0452, Reading: Bezug_Wirkleistung_Zaehler, Value: 1665.0452, Unit:
2017.02.06 18:21:04.158 5: DbLog LogDB -> processing event Timestamp: 2017-02-06 18:21:00, Device: SMA_Energymeter, Type: SMAEM, Event: Einspeisung_Wirkleistung: 0.0, Reading: Einspeisung_Wirkleistung, Value: 0.0, Unit:
2017.02.06 18:21:04.159 5: DbLog LogDB -> processing event Timestamp: 2017-02-06 18:21:00, Device: SMA_Energymeter, Type: SMAEM, Event: Einspeisung_Wirkleistung_Zaehler: 1718.8621, Reading: Einspeisung_Wirkleistung_Zaehler, Value: 1718.8621, Unit:
2017.02.06 18:21:04.159 5: DbLog LogDB -> processing event Timestamp: 2017-02-06 18:21:01, Device: MySTP_5000, Type: SMAINVERTER, Event: etotal: 13003.739, Reading: etotal, Value: 13003.739, Unit:
2017.02.06 18:21:04.159 5: DbLog LogDB -> processing event Timestamp: 2017-02-06 18:21:01, Device: MySTP_5000, Type: SMAINVERTER, Event: 0.000, Reading: state, Value: 0.000, Unit:
2017.02.06 18:21:04.159 5: DbLog LogDB -> processing event Timestamp: 2017-02-06 18:21:01, Device: Dum.Energy, Type: DUMMY, Event: TotalConsumption: 392.3, Reading: TotalConsumption, Value: 392.3, Unit:
2017.02.06 18:21:04.175 5: DbLog LogDB -> 13 of 13 events successfully inserted into table history
2017.02.06 18:21:04.193 5: DbLog LogDB -> 13 of 13 events successfully updated in table current
2017.02.06 18:21:04.220 5: DbLog LogDB -> DbLog_PushAsync finished


Kannst auch mal versuchen deine Current neu aufzubauen. Lösche den Inhalt mit "delete from current;" und lass die Einträge neu reinlaufen.

Die andere Sache mit dem texttospeech ist ja höchst mysteriös. Ich schau mir deinen Aufruf noch genauer an, aber am Aufbau von DbLog_Get ist nichts geändert. Also muß der Aufruf passen wenn er nicht neu ist.
Verwirrend ist auch der letzte Log von 1907. Schade dass es nur Log-Fragmente sind. Sieht aber tatsächlich so aus das:

2017-02-03 18:54:40   myTTS   cache/55a63bb70aea0a090e1bb93f45e9350f.mp3   Usage   Text2Speech   Dieser Testtext muellt meine Datenbank voll

aufgeteilt wird und dann natürlich in der DB landet. SQLite ist offensichtlich nicht so restriktiv wenn das Feld TIMESTAMP nicht wirklich einen Timestamp enthält. Hast du im texttospeech eine eigene SplitFn definiert ?
Vllt. hilft es schon wenn 1907 den verbose mode runter setzt. Ich denke die Select-Ausgabe kommt von texttospeech mit verbose=4.

Ich schau mal noch weiter. Vllt. fällt mir noch etwas auf...

Grüße
Heiko

[DS_Starter]

Hallo sunny,

erstmal eine gute Genesung !! Ist ja jetzt leider die Grippe Jahreszeit 

Dein Log habe ich durchgesehen und mir sind einige Dinge aufgefallen, die vllt. nicht jedes für sich aber in Summe doch so eigenartige Effekte verursachen können.
Habe das Wesentliche zusammengetragen:

Es kommen immer wieder Einträge vor die darauf schließen lassen dass du Plots hast welche die current-Tabelle als Datenbasis haben:

Code Auswählen Erweitern

2017.02.06 17:09:40.498 4: Processing Statement: SELECT
                  TIMESTAMP,
                  DEVICE,
                  READING,
                  VALUE
                   FROM history WHERE 1=1 AND DEVICE  = '8_Aussen_Treppe' AND READING = 'Temperatur' AND TIMESTAMP >= '2017-02-06 00:00:00' AND TIMESTAMP < '2017-02-07 00:00:01' ORDER BY TIMESTAMP
2017.02.06 17:09:40.567 3: Defining DbLog SVG-Plots with :CURRENT is deprecated. Please define DbLog SVG-Plots with :HISTORY instead of :CURRENT. (define <mySVG> SVG <DbLogDev>:<gplotfile>:HISTORY)

Schau mal ob und wo das der Fall ist.

Weiterhin kommt häufig die Meldung:

Code Auswählen Erweitern

2017.02.06 17:09:33.111 4: Processing Statement: SELECT
                  TIMESTAMP,
                  DEVICE,
                  READING,
                  VALUE
                   FROM history WHERE 1=1 AND DEVICE  = '9_hz_Kessel' AND READING = 'Temperatur' AND TIMESTAMP >= '2017-02-06 00:00:00' AND TIMESTAMP < '2017-02-07 00:00:01' ORDER BY TIMESTAMP
2017.02.06 17:09:35.819 2: DbLog myDbLog -> Error: DBD::SQLite::st execute_array failed: database disk image is malformed [err was 11 now 2000000000]
executing 20 generated 20 errors at /opt/fhem/FHEM/93_DbLog.pm line 1332.


Das ist nicht gut und deutet auf eine korrupte DB hin. Im Netz findet man Hinweise zur Reparatur, unter anderem hier:
http://froebe.net/blog/2015/05/27/error-sqlite-database-is-malformed-solved/

Und dann gibt es häufige Einträge der Art:

Code Auswählen Erweitern

2017.02.06 17:10:10.433 1: FHEMWEB SSL/HTTPS error:  SSL connect accept failed because of handshake problems error:14094416:SSL routines:SSL3_READ_BYTES:sslv3 alert certificate unknown

Auch diese Fehler sind sicherlich für einen stabilen Browser Seitenaufbau nicht förderlich.

Das Logging an sich funktioniert (bis auf die database disk image is malformed -Fehler) einwandfrei.

Ich hoffe du kommst damit weiter und bist bald wieder auf dem Posten ...

EDIT: sunny, das Hauptproblem ist IMHO die DB-Korruption. Das erklärt auch wieso sich der Effekt im asynchronen Modus verstärkt. In diesem Modus werden viel mehr Daten im Block nicht in die DB geschrieben wenn der Insert auf eine Korruption trifft und kein Commit stattfindet. Im Synchronen Mode sind die "Fehlhäppchen" kleiner.

viele Grüße
Heiko

[DS_Starter]

Hallo friesenjung,

bedeutet also es gilt immer nur je 1x nach dem set-Kommando und ich aktivier es immer vor dem Backup mittels at oder doif. richtig?

Ja, genauso. Falls dein X im "reopen X" mal zu kurz sein sollte und die DB noch nicht wieder da wäre, ist das auch nicht so schlimm. DbLog versucht dann in regelmäßigen ein reconnect und macht weiter sobald die DB wieder online ist.

Grüße
Heiko

[DS_Starter]

Hallo Tobias,

ich habe, glaube ich, zumindest einen Ansatzpunkt gefunden obwohl der erstmal nichts mit dem "processing event" zu tun hat.
Das DbLog_Push-Kommando passt nicht mehr. Du verwendest:

Code Auswählen Erweitern

DbLog_Push($defs{$DbLogDev}, "Current", TimeNow(), $hash->{NAME} ."|". $file, $hash->{TYPE}, $text, "Usage", $NewValue, "");

Wir verwenden ja nun ein array-insert. Wenn du weiterhin DbLog_Push verwenden willst müßtest du es sinngemäß so aufbauen:

Code Auswählen Erweitern


my $row = ($timestamp."|".$dev_name."|".$dev_type."|".$event."|".$reading."|".$value."|".$unit);
push(@row_array, $row);
my $error = DbLog_Push($dblog-hash, 1, @row_array);


Besser wäre vielleicht das unabhängige DbLog_ExecSQL-Kommando zu verwenden. Du übergibst nur das dblog-hash und das zusammengestellte SQL-Kommando:

Code Auswählen Erweitern

INSERT INTO current (TIMESTAMP, DEVICE, TYPE, EVENT, READING, VALUE, UNIT) VALUES (x,x,x,x,x,x,x)

Der Code von DbLog_ExecSQL sieht so aus:

Code Auswählen Erweitern


sub DbLog_ExecSQL($$)
{
  my ($hash,$sql)= @_;
  Log3 $hash->{NAME}, 4, "Executing $sql";
  my $dbh = DbLog_ConnectNewDBH($hash);
  return if(!$dbh);
  my $sth = DbLog_ExecSQL1($hash,$dbh,$sql);
  if(!$sth) {
    #retry
    $dbh->disconnect();
    $dbh = DbLog_ConnectNewDBH($hash);
    return if(!$dbh);
    $sth = DbLog_ExecSQL1($hash,$dbh,$sql);
    if(!$sth) {
      Log3 $hash->{NAME}, 2, "DBLog retry failed.";
      return 0;
    }
    Log3 $hash->{NAME}, 2, "DBLog retry ok.";
  }
  return $sth;
}

sub DbLog_ExecSQL1($$$)
{
  my ($hash,$dbh,$sql)= @_;

  my $sth = $dbh->do($sql);
  if(!$sth) {
    Log3 $hash->{NAME}, 2, "DBLog error: " . $DBI::errstr;
    return 0;
  }
  return $sth;
}


Schau mal ob du damit weiterkommst.

Grüße
Heiko

[DeeSPe]

DbLog_ExecSQL verwende ich auch im FileLogConvert Modul und das funktioniert super damit!!!
Kann ich nur empfehlen.

Gruß
Dan

[Tobias]

@Heiko, funktioniert
Modul Text2Speech angepasst und eingecheckt

[JoeALLb]

@Heiko, funktioniert
Modul Text2Speech angepasst und eingecheckt

Hallo Tobias,

Ich habe 3 DbLog_Devices und das Modul nimmt eine falsche Instanz.
Diese Instanz ist rein für tests gedacht und schreibt in eine andere Datenbank...
Sollte nicht geprüft werden, ob die gesuchte DbLog-Instanz im Define-Regex das Text2Speech-Modul erlaubt?

sG
Joe

[marvin78]

Tobias ist der Meinung, dass man nur eine DBLog Instanz braucht. So oder ähnlich hat er es mal geäußert. Ich habe versucht zu erklären, dass es Fälle gibt, in denen das sehr wohl notwendig ist. Ich habe aber nicht verfolgt, ob er das nochmal kommentiert hat.

[Tobias]

ich versteh nicht wie man 2 braucht, aber sei es drum, mir fällt  noch nix intelligentes ein um die richtige INstanz zu erwischen

[MichaelT]

Hallo Heiko,

habe 2.11.4 bei mir im Einsatz.
Falls was auffälliges passiert melde ich mich.

Gruß
Michael

[DS_Starter]

Danke Michael !

Welche DB hast du ?