93_DbLog (MYSQL) funktioniert maximal 10 Minuten.

Begonnen von betateilchen, 16 Februar 2014, 21:07:52

Vorheriges Thema - Nächstes Thema

betateilchen

1. fhem wird gestartet


2014.02.16 20:33:50 3: Connecting to database mysql:database=fhemLog;host=192.168.123.158;port=3306 with user bbb-fhem
2014.02.16 20:33:50 3: Connection to db mysql:database=fhemLog;host=192.168.123.158;port=3306 established for pid 9207
2014.02.16 20:33:50 3: Connection to db mysql:database=fhemLog;host=192.168.123.158;port=3306 established


2. Das Logging funktioniert prima...


| 2014-02-16 20:33:51 | sz_RT           | CUL_HM     | battery: ok                        | battery        | ok                    |       |
| 2014-02-16 20:33:51 | sz_RT           | CUL_HM     | measured-temp: 20.6                | measured-temp  | 20.6                  |       |
| 2014-02-16 20:33:51 | sz_RT           | CUL_HM     | desired-temp: 12                   | desired-temp   | 12                    |       |
| 2014-02-16 20:33:51 | sz_RT           | CUL_HM     | actuator: 0 %                      | actuator       | 0                     |       |
| 2014-02-16 20:33:52 | ku_TC_Climate   | CUL_HM     | measured-temp: 21.7                | measured-temp  | 21.7                  |       |
| 2014-02-16 20:33:52 | ku_TC_Climate   | CUL_HM     | desired-temp: 16                   | desired-temp   | 16                    |       |
| 2014-02-16 20:33:52 | ku_TC_Climate   | CUL_HM     | humidity: 48                       | humidity       | 48                    |       |


3. ... maximal zehn Minuten


| 2014-02-16 20:41:37 | bd_RT           | CUL_HM     | measured-temp: 23.5                | measured-temp  | 23.5                  |       |
| 2014-02-16 20:41:37 | bd_RT           | CUL_HM     | desired-temp: 16                   | desired-temp   | 16                    |       |
| 2014-02-16 20:41:37 | bd_RT           | CUL_HM     | actuator: 0 %                      | actuator       | 0                     |       |


Danach nix mehr. Das Verhalten ist beliebig oft reproduzierbar. Nach einem rereadcfg funktioniert das Ganze wieder 10 Minuten.
Das Problem betrifft nur mysql - die sqlite Variante läuft völlig problemlos.

Im Logfile von fhem gibt es keinen Hinweis auf ein Problem um 20:41.xx Uhr - auch nicht bei höchstem verbose-Level.
-----------------------
Formuliere die Aufgabe möglichst einfach und
setze die Lösung richtig um - dann wird es auch funktionieren.
-----------------------
Lesen gefährdet die Unwissenheit!

betateilchen

Ich habe einen Verdächtigen eingekreist: die DHCP Lease-Dauer auf MySQL-Serverseite. Immer wenn die IP (des MySQL-Server) aktualisiert (aber nicht geändert!) wurde, wurde das Logging abgebrochen.

Bedenklich finde ich allerdings, dass 93_DbLog nichts davon mitbekommt, dass in die Datenbank tatsächlich gar nicht mehr geloggt werden kann.

Im Moment läuft das Logging seit knapp zwei Stunden unterbrechungsfrei durch, nachdem ich meinen DHCP Server angewiesen habe, die DHCP-Lease für den MySQL Server auf "infinite" zu setzen.
-----------------------
Formuliere die Aufgabe möglichst einfach und
setze die Lösung richtig um - dann wird es auch funktionieren.
-----------------------
Lesen gefährdet die Unwissenheit!

erwin

Hi Betateilchen,
ich fürchte, ich muss mich an diesen Thread anhängen....
Ich hatte bis zum 25.Jänner manchmal die folgenden Einträge im Log:
2014.01.24 20:08:14 2: DbLog: Failed to insert new readings into database: DBD::mysql::db begin_work failed: Turning off AutoCommit failed at ./FHEM/93_DbLog.pm line 404.

2014.01.24 20:08:14 3: Connecting to database mysql:database=fhem;host=192.168.5.245;port=3306 with user fhemuser
2014.01.24 20:08:14 3: Connection to db mysql:database=fhem;host=192.168.5.245;port=3306 established for pid 21214

... ich weiß, mein Fehler, duplicate records in die Datenbank zu schicken, ABER nach ein oder zwei retries ging alles wie gewohnt weiter -
Ähnliche Fehler gabs auch, falls ich den SQL-daemon gestoppt/gestartet habe, oder die Netzwerkverbindung kurz weg war...

Seit dem Update ist offensichtlich die Fehlertoleranz des DbLog Moduls schlechter geworden:
DBD::mysql::st execute failed: Duplicate entry 'Bad_Thermostat-temperature_avg_day-2014-01-31 00:02:44' for key 'PRIMARY' at ./FHEM/93_DbLog.pm line 398.
DBD::mysql::db begin_work failed: Already in a transaction at ./FHEM/93_DbLog.pm line 390.
DBD::mysql::db begin_work failed: Already in a transaction at ./FHEM/93_DbLog.pm line 390.
DBD::mysql::db begin_work failed: Already in a transaction at ./FHEM/93_DbLog.pm line 390.

und das hört nicht mehr auf und es wird auch nichts geloggt, bis zum nächsten FHEM restart.
Wie gesagt, leicht reproduzierbar: restart SQL-Server, Netzwerk-Problem, oder (jaja blöd von mir: duplicate entries)...
l.g. erwin
FHEM aktuell auf RaspberryPI Mdl 1-4
Maintainer: 00_KNXIO.pm 10_KNX.pm
User: CUNO2 (868 SLOWRF) - HMS100xx, FS20, FHT, 1-Wire  - 2401(iButton), 18x20, 2406, 2413 (AVR), 2450,..,MQTT2, KNX, SONOFF, mySENSORS,....
Hardware:  Busware ROT, Weinzierl IP731, 1-Wire GW,...

betateilchen

Hallo erwin,

DBD::mysql::db begin_work failed: Already in a transaction at ./FHEM/93_DbLog.pm line 390.

Das ist aber ein anderer Fehler ;)

-----------------------
Formuliere die Aufgabe möglichst einfach und
setze die Lösung richtig um - dann wird es auch funktionieren.
-----------------------
Lesen gefährdet die Unwissenheit!

Tobias

@erwin, sollte mit dem letzten Update beseitigt sein...
Wenn nicht, bitte Info
Maintainer: Text2Speech, TrashCal, MediaList

Meine Projekte: https://github.com/tobiasfaust
* PumpControl v2: allround Bewässerungssteuerung mit ESP und FHEM
* Ein Modbus RS485 zu MQTT Gateway für SolarWechselrichter

betateilchen

Hallo Tobias,

93_DbLog ist (bei mir zumindest) extrem unzuverlässig, wenn der MySql-Server ausserhalb von localhost läuft.
Es scheint dann nicht mitzubekommen, wenn die Verbindung nicht mehr existiert und gar nicht mehr geloggt werden kann.

Viele Grüße
Udo
-----------------------
Formuliere die Aufgabe möglichst einfach und
setze die Lösung richtig um - dann wird es auch funktionieren.
-----------------------
Lesen gefährdet die Unwissenheit!

JoeALLb

Ich deaktiviere Dblog gerne,  wenn der mysql neu starten muss.  Wenn ich das deaktivieren während einer Transaktion mache,  connected er danach nicht wieder und meckert immer über die Transaktion. Nur ein restart  hilft dann.


Gesendet von meinem Xperia Pro mit Tapatalk

FHEM-Server auf IntelAtom+Debian (8.1 Watt), KNX,
RasPi-2 Sonos-FHEM per FHEM2FHEM,RasPi-3 Versuchs-RasPi für WLAN-Tests
Gateways: DuoFern Stick, CUL866 PCA301, CUL HM, HMLan, JeeLink, LaCrosse,VCO2
Synology. Ardurino UNO für 1-Wire Tests, FB7270

betateilchen

genau das ist das Problem: eine unterbrochene Verbindung wird nicht wieder neu aufgebaut, weil dieser Fall überhaupt nicht abgefangen wird.

Das eingangs beschriebene DHCP Problem ist nur ein kleiner Teil des ganzen Problems. Es verbessert die Situation, aber es hilft nicht dauerhaft und stabil.
-----------------------
Formuliere die Aufgabe möglichst einfach und
setze die Lösung richtig um - dann wird es auch funktionieren.
-----------------------
Lesen gefährdet die Unwissenheit!

Tobias

Wenn ihr eine Idee habt nehme ich einen Patch gerne entgegen:)
Maintainer: Text2Speech, TrashCal, MediaList

Meine Projekte: https://github.com/tobiasfaust
* PumpControl v2: allround Bewässerungssteuerung mit ESP und FHEM
* Ein Modbus RS485 zu MQTT Gateway für SolarWechselrichter

betateilchen

#9
Schwierig. Dazu müsste man das Modul komplett redesignen.


  • Bestimmte Anzahl Logeinträge cachen
  • Wenn der Eimer voll ist, Verbindung zur Datenbank aufbauen
  • Den Eimer in die Datenbank auskippen
  • Verbindung zur Datenbank wieder schließen

Alternativ: nach dem Schreiben auf die Datenbank einen Rückleseversuch machen, wenn der schiefgeht, reagieren.

Was ich noch nicht debugged habe: Normalerweise kommt doch ein affectedRow auch bei einem Insert - was passiert, wenn das 0 zurückliefert? Bzw: was kommt zurück, wenn der Fall eingetreten ist, dass das Insert fehlschlägt?
-----------------------
Formuliere die Aufgabe möglichst einfach und
setze die Lösung richtig um - dann wird es auch funktionieren.
-----------------------
Lesen gefährdet die Unwissenheit!

Tobias

Mm. Gibt es keinen Fehler beim schreiben wenn die Verbindung weg ist? Dann könnte man darauf reagieren

Gesendet von meinem ALCATEL ONE TOUCH 997D mit Tapatalk

Maintainer: Text2Speech, TrashCal, MediaList

Meine Projekte: https://github.com/tobiasfaust
* PumpControl v2: allround Bewässerungssteuerung mit ESP und FHEM
* Ein Modbus RS485 zu MQTT Gateway für SolarWechselrichter

betateilchen

#11
Doch, der würde eigentlich in $rv_ih und $rv_ic stehen, aber darum kümmert sich niemand, weil nur geprüft wird, ob das eval {} einen Fehler liefert.


  eval {
    # insert into history
    if (lc($DbLogType) =~ m(history) ) {
      my $rv_ih = $sth_ih->execute(($timestamp, $device, $type, $event, $reading, $value, $unit));
    }

    # update or insert current
    if (lc($DbLogType) =~ m(current) ) {
      my $rv_uc = $sth_uc->execute(($timestamp, $type, $event, $value, $unit, $device, $reading));
      if ($rv_uc == 0) {
        my $rv_ic = $sth_ic->execute(($timestamp, $device, $type, $event, $reading, $value, $unit));
      }
    }
  };

 
  if ($@) {
    Log3 $hash->{NAME}, 2, "DbLog: Failed to insert new readings into database: $@";
    $dbh->rollback();
    # reconnect
    $dbh->disconnect(); 
    DbLog_Connect($hash);
  }
  else {
    $dbh->commit();
    $dbh->{RaiseError} = 0; 
  }


Zitat von: DBI Doku zu executePerform whatever processing is necessary to execute the prepared statement. An undef is returned if an error occurs. A successful execute always returns true regardless of the number of rows affected, even if it's zero (see below). It is always important to check the return status of execute (and most other DBI methods) for errors

RaiseError ist zwar gesetzt, aber ich traue dem Frieden nicht wirklich. Ich muss mal debuggen, was da zurückkommt.

Im Moment ist es ja auch so, dass im Fehlerfall das Push fehlschlägt, eine Fehlermeldung ausgibt und ein rollback macht. Es wird nicht versucht, nach dem Reconnect das Ereignis erneut zu loggen.
-----------------------
Formuliere die Aufgabe möglichst einfach und
setze die Lösung richtig um - dann wird es auch funktionieren.
-----------------------
Lesen gefährdet die Unwissenheit!

JoeALLb

Sqlog blockiert meinen fhem, wenn der mysql die db reorganisiert. Das dauerte gestern 6 stunden. Hier wäre echt handlungsbedarf. Ich hatte gerne, dass er lokal in einer sqlite datensatze zwischenloggt, die mySql gerade nicht annehmen kann.
Kann man eigentlich das loggen nach current auch gleich entfernen, wenn das svg modul das schon als depreciated brandmarkt, oder wird das noch verwendet?

Gesendet von meinem Xperia Pro mit Tapatalk

FHEM-Server auf IntelAtom+Debian (8.1 Watt), KNX,
RasPi-2 Sonos-FHEM per FHEM2FHEM,RasPi-3 Versuchs-RasPi für WLAN-Tests
Gateways: DuoFern Stick, CUL866 PCA301, CUL HM, HMLan, JeeLink, LaCrosse,VCO2
Synology. Ardurino UNO für 1-Wire Tests, FB7270

betateilchen

Zitat von: JoeALLb am 20 Februar 2014, 18:00:11Ich hatte gerne, dass er lokal in einer sqlite datensatze zwischenloggt, die mySql gerade nicht annehmen kann.

Wenn Du jetzt allen ernstes verlangst, zwei verschiedene Datenbanksysteme installieren zu müssen, wirst Du in Kürze gesteinigt. Nimm Dich in acht 8)

Zitat von: JoeALLb am 20 Februar 2014, 18:00:11Kann man eigentlich das loggen nach current auch gleich entfernen,

Ich brauche das noch und ich wäre froh, wenn current auch in sqlite funktionieren würde.

Außerdem kannst du das loggen in current per Attribut einfach abschalten.
-----------------------
Formuliere die Aufgabe möglichst einfach und
setze die Lösung richtig um - dann wird es auch funktionieren.
-----------------------
Lesen gefährdet die Unwissenheit!

JoeALLb

Das abschalten ist mir schon klar,  aber kenne nur keinen Vorteil mehr davon und wollte es lieber entfernen,  als mir das nur nach history-loggen als defekt wünschen.

Gesteinigt?  Das nehme ich auf mich,  wenn ich dafür meine logeinträge retten kann...

Gesendet von meinem Xperia Pro mit Tapatalk

FHEM-Server auf IntelAtom+Debian (8.1 Watt), KNX,
RasPi-2 Sonos-FHEM per FHEM2FHEM,RasPi-3 Versuchs-RasPi für WLAN-Tests
Gateways: DuoFern Stick, CUL866 PCA301, CUL HM, HMLan, JeeLink, LaCrosse,VCO2
Synology. Ardurino UNO für 1-Wire Tests, FB7270