DbLog schreibt nach ein paar Minuten nicht mehr in die externe DB

[photon2000]

Hallo,
nach langem Suchen hier im Forum und dem Hinweis des Users Benni hoffe ich, dass ich hier die richtige Stelle für meine Frage getroffen habe.

Ich möchte das Loggen auf DbLog umstellen und habe deshalb FHEM experimentell auf einem zweiten Pi eingerichtet, ein paar Sensoren umgehängt und DbLog initialisiert.
Das Phänomen: Nach dem Starten des Systems (z.B. kompletter Restart des Pi) werden Readings sauber in die DB geschrieben, nach ein paar Minuten aber nicht mehr.

Meine Umgebung:
Bare metal Installation: Raspberry Pi B+,  Raspbian (neueste Version + apt-get update/upgrade) auf 4GB SD-Karte, Installation Enocean Pi Board, FHEM Installation + update (das letzte am 17.6.), DbLog Install, MySQL DB auf all-inkl Server, Zugriff aus dem lokalen Netz mittels HeidiSQL-Client getestet, DbLog initialisiert (musste noch das DBI.pm und den mysql-client nachinstallieren), EnOcean Switch gedrückt, Readings tauchen in der DB auf. Bis nach ein paar Minuten...

Was habe ich schon probiert?
- Nach den plotfork-Hinweisen hier im Forum habe ich alle erstellten SVG Plots wieder gelöscht -> keine Änderung (das attr plotfork ist in WEB aber auch auf "0" gesetzt)
- Verbose Level von DbLog auf 5 gesetzt: Nun werden die Readings im FHEM Log geloggt aber nach der Unterbrechung ist keine Fehlermeldung zu finden
- service fhem stop|start führt dazu, dass die Readings wieder in der DB landen; bis in ein paar Minuten (etwa zwischen 2 und 10)
- manchmal hilft ein "set myDbLog reopen", aber auch nicht immer. Dann ist ein fhem Neustart nötig
- STATE im DbLog ist dabei durchgängig auf "connected"

In die Filelogs werden die Readings übrigens auch nach dem DbLog "Ausstieg" fleißig weiter geschrieben. Deshalb gehe ich davon aus, dass es nicht an dem Zweig Sensoren -> EnOceanPi-Board -> FHEM liegt.
Die Datenbank ist mittels HeidiSQL-Client (Windows) auch nach dem DbLog "Ausstieg" erreichbar. Da da auch andere produktive DBs drauf laufen schliesse ich die DB als Fehlerquelle auch aus.

Jetzt bin ich mit meinem Latein am Ende  und hoffe auf Unterstützung von euch.

Was kann ich noch tun?


Besten Gruß.

[dev0]

Falls dein Pi über WLAN angebunden ist, könnte es einen Versuch wert sein, das WLAN zu deaktivieren und ein Kabel zu benutzten.

/Uli

[photon2000]

Hallo Uli,
danke für die Antwort.
Der Pi ist kabelgebunden im LAN. Ich arbeite auch auf dem FHEMWEB und nach einem "set myDbLog reopen" werden die readings auch (für ein paar Minuten) in die entfernete Datenbank geschrieben.

[dev0]

In /var/log/messages hast Du wahrscheinlich schon nach Ereignissen gesucht... Um Netzwerkunterbrechungen ganz auszuschließen könntest Du noch versuchen mit einem schnellen Dauerping (sudo ping -i 0.05 DEIN_ROUTER) nach packet loss zu suchen. Besser wäre noch Wireshark, aber dafür muss man sich auch etwas mit IP Paketen und TCP Verbindungsaufbau auskennen.
Du könntest auch testweise einen lokalen mysql server kurz aufsetzen um zu testen ob dort auch die Abbrüche auftreten.

/Uli

[ChrisD]

Hallo,

Wenn die Verbindung zur Datenbank verloren geht kann es passieren dass sie nicht mehr richtig aufgebaut wird. Dies kann bei Verbindungsabbrüchen passieren, allerdings auch beim fork in FHEM. Leider wird in dem Fall auch keine Fehlermeldung ausgegeben. Du kannst zuerst versuchen in 93_DbLog.pm am Ende der Funktion DbLog_Log die Zeile

Code Auswählen Erweitern

Log3 $hash->{NAME}, 0, "DbLog: Error: $@" if ($@); hinzuzufügen.

Der Code sollte dann so

DbLog_Push($hash, 'History', $ts_le, $n, $t, $s, $reading, $v_le, $unit);
          }
        }
      }
    }
  };

  Log3 $hash->{NAME}, 0, "DbLog: Error: $@" if ($@);
 
  return "";
}

################################################################
#
# zerlegt uebergebenes FHEM-Datum in die einzelnen Bestandteile

aussehen.

Danach muss FHEM neu gestartet werden. Wenn das Schreiben fehlschlägt sollte im Log ein Eintrag zu finden sein.
 
Grüße,

ChrisD

[photon2000]

Vielen Dank für eure Unterstützung!

@ChrisD
Ich habe die Zeile in die 93_DbLog.pm eingebaut und siehe da:
Es kommen Fehlermeldungen, nachdem nichts mehr in die DB geschrieben wird. Jedesmal, wenn ein reading erzeugt wird (z.B. durch Drücken eines Tasters) wir eine Zeile erzeugt:

"DbLog: Error: DBD::mysql::db begin_work failed: Turning off AutoCommit failed at ./FHEM/93_DbLog.pm line 451."

Zeile 451 in 93_DbLog.pm ist:
  $dbh->begin_work();

Die Log-Ausgabe in Zeile 457 wird im Fehlerfall nicht mehr erzeugt.

Was kann ich noch tun, um den Fehler weiter einzugrenzen?
(libdbi-perl und libdbd-mysql-perl sind laut apt-get auf dem neuesten Stand)


@dev0
5000 schnelle Ping Pakete (nach deiner Anleitung) habe ohne Verlust den Router erreicht.

Gruß, photon2000.

[dev0]

5000 schnelle Ping Pakete (nach deiner Anleitung) habe ohne Verlust den Router erreicht.

Entscheidend ist genau der Moment, in dem die Verbindung zur Datenbank flöten geht...

[photon2000]

Hi dev0,

danke für den Hinweis.
Ich habe gerade parallel readings erzeugt und dabei die schnellen ping zum Router laufen lassen.
ping hat auch nach dem Auftreten des o.g. Fehlers ("DbLog: Error: DBD::mysql::db begin_work failed:..:") keine lost packages gezählt.
Also bis zum Router sollten die Verbindungsabbrüche als Ursache ausscheiden., oder?

[dev0]

Davon würde ich jetzt auch ausgehen. Ggf. kannst Du den Pingtest noch einmal direkt gegen den DB Server laufen lasssen.
Sonst hat ChrisD vielleicht noch weitere Ideen das auf Modulebene zu debuggen.

[ChrisD]

Hallo,

Du kannst versuchen Zeile 451 durch diesen Block zu ersetzen:

Code Auswählen Erweitern

  if ($hash->{DBMODEL} eq "MYSQL") {
      eval {
        $dbh->begin_work();
      };
      if($@) {
        Log 0,$@;
        DbLog_Connect($hash);
        $dbh->begin_work();
      }
  } else {
    $dbh->begin_work();
  } 
und FHEM neu zu starten. Der Code versucht die Verbindung neu aufzubauen wenn Daten geloggt werden sollen und ein Fehler auftritt. Damit wird zwar nicht das grundlegende Problem (Netzwerk oder fork) behoben, das Loggen sollte damit aber wieder funktionieren.

Grüße,

ChrisD

[photon2000]

Hallo ChrisD,

ich habe deinen Vorschlag gerade umgesetzt. Es funktioniert. Das Logging der Daten geht auch dann bis zur Datenbank durch, wenn der Fehler auftritt. Danke für den workaround!

Kann ich noch etwas Sinnvolles tun, um den Fehler weiter einzugrenzen?
Oder macht es Sinn, die Änderung dem Maintainer des Moduls zur Übernahme vorzuschlagen?
Sollte es an Verbindungsproblemen liegen, scheint doch das reconnecten sinnvoll zu sein.

Gruß, photon2000.

[ChrisD]

Hallo,

Kann ich noch etwas Sinnvolles tun, um den Fehler weiter einzugrenzen?

Wenn du sicher bist dass die Probleme nicht durch das Netzwerk kommen könntest du schauen welche Module du einsetzt die fork verwenden (z.B. OWServer oder SONOS). Eventuell könnte auch das letzte geloggte Event bevor es zum Fehler kommt einen Hinweis geben.

Oder macht es Sinn, die Änderung dem Maintainer des Moduls zur Übernahme vorzuschlagen?

Meiner Meinung nach sollte bei einem Verbindungsabbruch auf Grund von Netzwerkproblemen das Modul die Verbindung selbständig wieder herstellen. Für den Fall dass ein Nebenprozess die Verbindung schließt sollte dies besser an der Quelle behoben werden.

Der Code ist im Moment auch nur mit MySQL getestet, bevor er aufgenommen würde, müsste mit den anderen Datenbanktypen getestet werden.

Grüße,

ChrisD

[photon2000]

Hallo ChrisD,

ich habe mich nochmal etwas genauer mit den Ausgaben im fhem Logfile beschäftigt.

Hier gibt es das Phänomen, dass neben den Fehlermeldungen:

"DBD::mysql::db begin_work failed: Turning off AutoCommit failed at ./FHEM/93_DbLog.pm line 455."

auf die jetzt ja durch deinen Vorschlag in Post 9 mit einem reconnect reagiert wird, auch noch in der if-else-Anweisung
nach dem
DbLog_Connect($hash);
$dbh->begin_work();

ein Fehler geworfen wird (relativ häufig):
"2015.06.26 09:39:16 3: Connection to db mysql:database=d01e89cb;host=123456.kasserver.com;port=3306 established"
"2015.06.26 09:39:16 0: DbLog: Error: DBD::mysql::db begin_work failed: Turning off AutoCommit failed at ./FHEM/93_DbLog.pm line 460."

Zeile 460 ist das "$dbh->begin_work();" in der if-else-Anweisung
Also unmittelbar nach dem reconnect!

Unter diesen Umständen werden auch die aktuellen readings nicht in die Datenbank geschrieben.
Beim der nächsten Änderung von Sensorwerten werden dann readings wieder in die Datenbank geschrieben.
D.h. einige readings gehen "verloren" und landen nicht in der DB.

Ich werde jetzt mal mit einem define Eintrag die zu loggenden Werte einschränken.
Evtl. sind es bestimmte readings bei denen er aussteigt?
Was sagst du dazu?

Gruß, photon2000.

[ChrisD]

Hallo,

Dass die beim Reconnect anliegenden Daten verloren gehen liegt an einem Fehler im Code, hier eine verbesserte Version:

Code Auswählen Erweitern

  if ($hash->{DBMODEL} eq "MYSQL") {
      eval {
        $dbh->begin_work();
      };
      if($@) {
        Log 0,$@;
        DbLog_Connect($hash);
        $dbh= $hash->{DBH};
        $dbh->{RaiseError} = 1;
        $dbh->{PrintError} = 0; 
        $dbh->begin_work();
      }
  } else {
    $dbh->begin_work();
  } 


Kannst du testen ob es damit richtig funktioniert ?

Ich glaube nicht dass es an den Readings hängt, ich kann den Fehler in der Zwischenzeit mit einem simplen fork-Aufruf reproduzieren. Es liegt wahrscheinlich an einem der bei dir eingesetzten Module dass es zum Fehler kommt.

Grüße,

ChrisD

[photon2000]

Hallo ChrisD,

danke für deine Unterstützung!
Ich habe es gestern Abend noch ausprobiert. Es klappt. Jetzt gibt es nur noch die "Ausstiege" und das entsprechende reconnect in der Zeile:

Code Auswählen Erweitern

if ($hash->{DBMODEL} eq "MYSQL") {
      eval {
hier ->>       $dbh->begin_work();
      };
      if($@) {
        Log 0,$@;
        DbLog_Connect($hash);
        $dbh= $hash->{DBH};
        $dbh->{RaiseError} = 1;
        $dbh->{PrintError} = 0;
        $dbh->begin_work();
      }
  } else {
    $dbh->begin_work();
  }

Neu ist ein Loggineintrag in der DB vom device "myDbLog" vom Typ:

<TIMESTAMP>     myDbLog     DBLOG    connected    state    connected

So einen Eintrag gab es von gestern Abend 22:30 Uhr bis jetzt (ca. 9:30 Uhr)  105 mal.

Neben dem DbLog-Modul nutze ich (bewusst) nur noch das EnOcean-Modul (00_TCM.pm).

Gruß, photon2000.