93_DbLog - Umstellung Log-Funktion auf non-blocking

[DS_Starter]

Hallo Martin,

prima ... danke für die  Rückmeldung.

VG
Heiko

[Benni]

Probier mal die angehängte V2.10.5 bei dir ob das so zieht wie beabsichtigt.

Hallo Heiko,

leider nein! 

Die race condition bleibt anscheinend dieselbe: DbLog_Log kommt und das Sperr-Bit in HELPER ist zu dem Zeitpunkt noch nicht verfügbar.

Eine weitere Möglichkeit wäre evtl. ein Attribut um das eventlose update von CacheUsage in DbLog_Log im Asynch-Mode auf (User-)Wunsch abzuschalten. Dazu ist das Problem aber vllt. auch zu speziell.

Übrigens: Die Moduldatei meldet sich in den Internals noch als Version V2.10.4

Gruß Benni.

[DS_Starter]

Hi Benni,

komm, einen Versuch machen wir noch. Habe das Sperrbit in execmemcache etwas früher gesetzt und später gelöscht.
Das sollte doch ziehen ...
Die interne V ist auch korrigiert.

Grüße
Heiko

[Benni]

komm, einen Versuch machen wir noch.

Leider immer noch negativ 

[DS_Starter]

Leider immer noch negativ 

Schade ... der Versuch war es noch wert. Ich werde dann erstmal die 2.10.4 einchecken.
Vielleicht kriegen wir das noch anders hin.

Grüße
Heiko

[PatrickR]

Mahlzeit!

Zunächst erneut vielen Dank für die Updates. Ich logge ziemlich großzügig und lasse permanent apptime laufen. Da sieht man sehr gut, wie im asynchronen Modus nahezu sämtliche Laufzeiten deutlich nach unten gehen.

Hierzu eine Frage:
Was genau passiert im Fall eines fehlerhaften Datenbank-Connects im asynchronen Modus, d. h.:

Code Auswählen Erweitern


2017.01.20 06:13:20.002 3: DbLog DbLog: Error DBLog_execmemcache - DBI connect('database=fhem;host=mysql.prdom;port=3306','fhem',...) failed: Can't connect to MySQL server on 'mysql.prdom' (111) at ./FHEM/93_DbLog.pm line 1102.

Das passiert bei mir wenn ich Paketupdates des MySQL-Dienstes durchführe. Wird der Cache dann beim nächsten Connect erneut an die DB geschickt?

Patrick

[DS_Starter]

Hallo Patrick,

Wird der Cache dann beim nächsten Connect erneut an die DB geschickt?

So ist es. DbLog erkennt im asynchronen Modus bevor die Daten an den Hintergrundprozess gesendet werden dass die DB nicht erreichbar ist und hält die Daten im Cache. Wenn sie wieder verfügbar ist, werden sie in die DB geschrieben.
Du darfst natürlich FHEM in der Zeit nicht restarten. Der Cache ist im RAM und flüchtig.

Grüße
Heiko

[pc1246]

Moin
Jetzt muss ich leider auch mal nachfragen. Ich habe vorhin ein update gemacht, und jetzt (vielleicht auch schon vorher?) kann ich keine SVG's mehr editieren! Es gibt keine dropdowns fuer die Werte mehr. Da meine DB recht gross (14GB) ist, ist alles was ich darauf mache sehr langsam. Ein Count hat ca. 30 Minuten gedauert, Als ich dann das Problem entdeckt hatte habe ich ein reopen  gemacht, danach war fhem dann tot. Irgendwie hat zweimal reboot des RPI das fhem wieder erweckt. Im LOG stand folgendes:

Code Auswählen Erweitern

DBD::SQLite::db prepare failed: unable to open database file at ./FHEM/93_DbLog.pm line 955.
Ich wuerde die DB ja gerne einschrumpfen, aber momentan ist mir das sehr suspekt. Kann ich gefahrlos auf async umstellen? Soll ich lieber eine neue DB erstellen, und wenn ja wie?
Gruss Christoph

[JoeALLb]

Hallo Heiko,

vielen Dank für die Weiterentwicklung!!!

Läuft bisher ohne Auffälligkeiten, folgendes ist mir jedoch aufgefallen:
#1 Die Version von 2.10.5 wird intern noch als 2.10.4 angezeigt
# Wie bekannt, habe ich ja in der Datenbank einen PK eingefügt und bekomme daher Fehlermeldungen, die
   natürlich nichts mit dem Modul zu tun haben. Trotzdem habe ich dazu eine Frage:

Code Auswählen Erweitern

DBD::mysql::st execute_array failed: Duplicate entry 'temp.wz.innen-empfehlung-2017-01-22 20:05:41' for key 'PRIMARY' [err was 1062 now 2000000000] executing 176 generated 21 errors at ./FHEM/93_DbLog.pm line 1326.
Was passiert mit diesem Datensatz? Vermutlich wird nur dieser eine nicht in die Datenbank eingetragen? Da das Modul ja Fehler erkennt, hännte ich nun erwartet, dass dieser Datensatz im Cache verbleibt und
beim nächsten Zyklus wieder versucht wird, einzutragen. Dem ist aber nicht so. Löscht das Modul also Fehler dieses Typs?
Prinzipiell nutze ich diese Fehlerlogs gerade, um alle fehlerhaften Devices zu erkennen dort mich für eine Fehlerbereinigung einzusetzen... es macht ja keinen Sinn, gewisse Readings 2x zur selben Zeit mit dem selben Reading zu setzen....

[JoeALLb]

Ich wuerde die DB ja gerne einschrumpfen, aber momentan ist mir das sehr suspekt. Kann ich gefahrlos auf async umstellen? Soll ich lieber eine neue DB erstellen, und wenn ja wie?

Versuch doch mal bitte die neuere Version aus Post #407, so viel ich verstanden habe könnte diese das schon beheben...

[DS_Starter]

Halllo Christoph,

Es gibt keine dropdowns fuer die Werte mehr

Stelle bitte das Attr "DbLogType" auf "Current/History". Dann bekommst du auch die Drop-Down. Die 2.10.4 aus  #401 ist der letzte Stand.
Die 2.10.5 war nur für ein paar Versuche mit Benni.

DBD::SQLite::db prepare failed: unable to open database file at ./FHEM/93_DbLog.pm line 955.

Sagt aber tatsächlich dass deine DB nicht zugreifbar ist. Schau mal ob die vielleicht durch einen äußeren Prozess geblockt ist. Bei mir ist dass z.B. der Fall wenn ich meine Test-SQLite mit einem externen SQL-Editor öffne.

Hi Joe,

#1 Die Version von 2.10.5 wird intern noch als 2.10.4 angezeigt

Ja, das war nur ein Test mit Benni wegen seinen Events.

Grüße
Heiko

[DS_Starter]

Hi Joe,

Da das Modul ja Fehler erkennt, hännte ich nun erwartet, dass dieser Datensatz im Cache verbleibt und
beim nächsten Zyklus wieder versucht wird, einzutragen. Dem ist aber nicht so.

Momentan bin ich soweit, dass bei Nichtverfügbarkeit der DB oder wie bei Christoph die DB gelockt ist, dieser Zusatnd erkannt wird und dementsprechend die Daten im Cache verbleiben unm sie päter wieder einzufügen.
Andere Zustände die "tiefer" liegen kann ich momentan noch nicht abfangen, sondern nur als als Info bzw. Log ausgeben.

Grüße
Heiko

[JoeALLb]

Momentan bin ich soweit, dass bei Nichtverfügbarkeit der DB oder wie bei Christoph die DB gelockt ist, dieser Zusatnd erkannt wird und dementsprechend die Daten im Cache verbleiben unm sie päter wieder einzufügen.
Andere Zustände die "tiefer" liegen kann ich momentan noch nicht abfangen, sondern nur als als Info bzw. Log ausgeben.

Danke für die Erklärung. Bedeutet das dann aber, dass in solch einem Fall alle Datensätze des Arrays nicht eingefügt werden können, oder nur eben der eine, der den Fehler aufwirft.

Im Beispiel

Code Auswählen Erweitern

DBD::mysql::st execute_array failed: Duplicate entry 'temp.wz.innen-empfehlung-2017-01-22 20:05:41' for key 'PRIMARY' [err was 1062 now 2000000000] executing 176 generated 21 errors at ./FHEM/93_DbLog.pm line 1326.
würde ich mir dann eigentlich 21 solcher Fehlermeldungen erwarten.... ich bekomme aber nur eine.

[DS_Starter]

Hi Joe,

der bei denen der Fehler auftritt.
Mach dir doch mal verbose 5 an. Es sollte dann ersichtlich sein wieviele Datansätze (Ist/Soll) in die DB eingefügt wurden.
Probiers mal ...

LG
Heiko

[stromer-12]

mit der 2.10.2 sieht das bei mir so aus:

Code Auswählen Erweitern

2017.01.22 10:47:17.621 2: DbLog myDbLog -> Failed to insert into current: fb_call, event, Status = 0
2017.01.22 10:47:17.622 2: DbLog myDbLog -> Failed to insert into current: fb_call, direction, Status = 0
2017.01.22 10:47:17.623 2: DbLog myDbLog -> Failed to insert into current: fb_call, external_connection, Status = 0
2017.01.22 10:47:17.623 2: DbLog myDbLog -> Failed to insert into current: fb_call, internal_number, Status = 0
2017.01.22 10:47:17.624 2: DbLog myDbLog -> Failed to insert into current: fb_call, external_number, Status = 0
2017.01.22 10:47:17.624 2: DbLog myDbLog -> Failed to insert into current: fb_call, call_id, Status = 0
2017.01.22 10:47:17.624 2: DbLog myDbLog -> Failed to insert into current: fb_call, external_name, Status = 0
2017.01.22 10:47:17.625 2: DbLog myDbLog -> Failed to insert into current: fb_call, event, Status = 0
2017.01.22 10:47:17.625 2: DbLog myDbLog -> Failed to insert into current: fb_call, direction, Status = 0
2017.01.22 10:47:17.625 2: DbLog myDbLog -> Failed to insert into current: fb_call, external_connection, Status = 0
2017.01.22 10:47:17.626 2: DbLog myDbLog -> Failed to insert into current: fb_call, internal_number, Status = 0
2017.01.22 10:47:17.627 2: DbLog myDbLog -> Failed to insert into current: fb_call, external_number, Status = 0
2017.01.22 10:47:17.628 2: DbLog myDbLog -> Failed to insert into current: fb_call, internal_connection, Status = 0
2017.01.22 10:47:17.629 2: DbLog myDbLog -> Failed to insert into current: fb_call, call_id, Status = 0
2017.01.22 10:47:17.630 2: DbLog myDbLog -> Failed to insert into current: fb_call, external_name, Status = 0
2017.01.22 10:47:17.632 2: DbLog myDbLog -> Failed to insert into current: fb_call, event, Status = 0
2017.01.22 10:47:17.632 2: DbLog myDbLog -> Failed to insert into current: fb_call, internal_connection, Status = 0
2017.01.22 10:47:17.634 2: DbLog myDbLog -> Failed to insert into current: fb_call, external_name, Status = 0
2017.01.22 10:47:17.635 2: DbLog myDbLog -> Failed to insert into current: fb_call, call_id, Status = 0
2017.01.22 10:47:17.636 2: DbLog myDbLog -> Failed to insert into current: fb_call, external_connection, Status = 0
2017.01.22 10:47:17.637 2: DbLog myDbLog -> Failed to insert into current: fb_call, internal_number, Status = 0
2017.01.22 10:47:17.638 2: DbLog myDbLog -> Failed to insert into current: fb_call, direction, Status = 0
2017.01.22 10:47:17.640 2: DbLog myDbLog -> Failed to insert into current: fb_call, external_number, Status = 0