[93_DbLog.pm] GELÖST: "get ... webchart ..." schreibt Logdatei voll

[alkazaa]

Moin!

Einigen Nutzern von SmartVisu ist aufgefallen, dass die Funktion "get ... webchart ..." ihren SQL-query response immer in die zentrale FHEM logdatei schreibt (die dadurch natürlich rvoll"gespammt" wird).

Das passiert unabhängig vom verbose-Wert der verwendeten DbLog Instanz oder dem verbose-Werts der verwendeten fronthem-Instanz. Nur ein globales verbose<3 unterdrückt das vollspammen (ist aber inakzeptabel).

Verantwortlich ist diese Zeile

Code Auswählen Erweitern

my $string = main::fhem('get ' . $args[0] . ' - webchart ' . $from . ' ' . $to . ' ' . $device . ' ' . $duration . ' TIMESTAMP ' . $reading); in [99_fronthemUtils.pm], in welcher "get ,,, webchart ..." aus der [93_DbLog.pm] aufgerufen wird. Das get...webchart wiederum lenkt zur sub DbLog_chartQuery weiter, die dann den jsonstring zurück liefert, der in fronthemUtils ausgewertet wird (und der leider auch immer in der zentralen Logdatei landet).

Als workaround habe ich das hier versucht, aber leider mit den beschriebenen Nebenwirkungen.

Meine Fragen an die Experten:

• Wie kann man das loggen der SQL Antwort eleganter verhindern (bzw. vom verbose setting in DbLog steuern lassen)?
  
• Und wieso tritt das bei SVG Plots nicht auf, wo doch laut commandref das "get ,,, webchart ..." für das originäre FHEM-charting frontend benutzt wird?

(In Wirklichkeit scheint aber wohl das "get ,,, webchart ...", bzw. die sub DbLog_chartQuery gar nicht genutzt zu werden. Könnte es sein, dass das  "get ,,, webchart ..." mehr oder weniger ungenutztes "Totholz" im code ist? Der Effekt hätte doch sonst an anderer Stelle irgendwie auffallen müssen.)


Ich hoffe das Problem hinreichend verständlich beschrieben zu haben,
Beste Grüße
Franz

[DS_Starter]

Hallo Franz,

Wie kann man das loggen der SQL Antwort eleganter verhindern (bzw. vom verbose setting in DbLog steuern lassen)

Erst muss man herausfinden wer/was überhaupt die Log-Meldung schreibt. In den relevanten Codeblöcken in DbLog sehe ich momentan noch keine Verdächtigen.

Und wieso tritt das bei SVG Plots nicht auf, wo doch laut commandref das "get ,,, webchart ..." für das originäre FHEM-charting frontend benutzt wird

siehe 1 

Poste doch bitte Auszüge aus dem Log. Das hast du leider vergessen.

Grüße,
Heiko

[alkazaa]

Hallo Heiko,
Danke für die Rückmeldung.

Hier etwas mehr Infos zum Problem:
1) Für ein tracing des Ablaufs habe ich in 93_DbLog.pm Debug() Aufrufe eingefügt:

Code Auswählen Erweitern

########### Auszug aus 93_DbLog.pm mit eingefügtem Debug() statement zum tracen:
  if($inf eq "-") {
      $inf = "history";
  }

  if($outf eq "int" && $inf eq "current") {
      $inf = "history";
      Log3 $hash->{NAME}, 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)";
  }

  if($outf eq "int") {
      $outf = "-";
      $internal = 1;
  } elsif($outf eq "array") {

  } elsif(lc($outf) eq "webchart") {
      # redirect the get request to the DbLog_chartQuery function
      Debug("Hier gibt DbLog_Get an DbLog_chartQuery weiter");
  return DbLog_chartQuery($hash, @_);
 
########### Auszug aus DbLog_chartQuery.pm mit eingefügten Debug() statements zum tracen:
sub DbLog_chartQuery($@) {

    my ($sql, $countsql) = DbLog_prepareSql(@_);

    Debug("Hier ist der Einstieg in DbLog_chartQuery");
if ($sql eq "error") {
       return DbLog_jsonError("Could not setup SQL String. Maybe the Database is busy, please try again!");
    } elsif ($sql eq "errordb") {
       return DbLog_jsonError("The Database Type is not supported!");
...
...
...
   
Debug("Hier wird DbLog_chartQuery verlassen");
return $jsonstring;
}

2) In 99_fronthemUtils.pm (siehe Anhang) habe ich meinen workaround-code zunächst mal auskommentiert (außer der Debug-Zeile):

Code Auswählen Erweitern

#my $oldverbose = main::AttrVal("global","verbose","3");
#main::fhem("attr global verbose 2");
main::Debug('get ' . $args[0] . ' - webchart ' . $from . ' ' . $to . ' ' . $device . ' ' . $duration . ' TIMESTAMP ' . $reading);
my $string = main::fhem('get ' . $args[0] . ' - webchart ' . $from . ' ' . $to . ' ' . $device . ' ' . $duration . ' TIMESTAMP ' . $reading);
#main::fhem("attr global verbose " . $oldverbose);

3) Das steht dann nach dem Aufruf der SmartVisu-Seite in der Log-Datei:

Code Auswählen Erweitern

2020.12.18 10:15:26 1: DEBUG>get logdb - webchart 2020-12-18_06:15:26 2020-12-18_10:15:26 ESP_Easy_1 timerange TIMESTAMP PPM
2020.12.18 10:15:26 1: DEBUG>Hier gibt DbLog_Get an DbLog_chartQuery weiter
2020.12.18 10:15:26 1: DEBUG>Hier ist der Einstieg in DbLog_chartQuery
2020.12.18 10:15:26 1: DEBUG>Hier wird DbLog_chartQuery verlassen
2020.12.18 10:15:26 3: get logdb - webchart 2020-12-18_06:15:26 2020-12-18_10:15:26 ESP_Easy_1 timerange TIMESTAMP PPM : {"data":[{"TIMESTAMP":"2020-12-18 06:21:02","VALUE":"402.00"},{"TIMESTAMP":"2020-12-18 06:24:12","VALUE":"403.00"},{"TIMESTAMP":"2020-12-18 06:27:22","VALUE":"402.00"},{"TIMESTAMP":"2020-12-18 06:30:32","VALUE":"400.00"},{"TIMESTAMP":"2020-12-18 06:36:52","VALUE":"402.00"},{"TIMESTAMP":"2020-12-18 06:40:02","VALUE":"401.00"},{"TIMESTAMP":"2020-12-18 06:43:12","VALUE":"404.00"},{"TIMESTAMP":"2020-12-18 06:46:22","VALUE":"401.00"},{"TIMESTAMP":"2020-12-18 06:49:32","VALUE":"402.00"},{"TIMESTAMP":"2020-12-18 06:52:42","VALUE":"404.00"},{"TIMESTAMP":"2020-12-18 06:55:52","VALUE":"403.00"},{"TIMESTAMP":"2020-12-18 06:59:02","VALUE":"402.00"},{"TIMESTAMP":"2020-12-18 07:02:12","VALUE":"404.00"},{"TIMESTAMP":"2020-12-18 07:05:22","VALUE":"403.00"},{"TIMESTAMP":"2020-12-18 07:08:32","VALUE":"401.00"},{"TIMESTAMP":"2020-12-18 07:11:42","VALUE":"402.00"},{"TIMESTAMP":"2020-12-18 07:18:02","VALUE":"400.00"},{"TIMESTAMP":"2020-12-18 07:21:12","VALUE":"401.00"},{"TIMESTAMP":"2020-12-18 07:24:22","VALUE":"402.00"},{"TIMESTAMP":"2020-12-18 07:27:32","VALUE":"404.00"},{"TIMESTAMP":"2020-12-18 07:30:42","VALUE":"401.00"},{"TIMESTAMP":"2020-12-18 07:33:52","VALUE":"403.00"},{"TIMESTAMP":"2020-12-18 07:37:02","VALUE":"401.00"},{"TIMESTAMP":"2020-12-18 07:40:12","VALUE":"403.00"},{"TIMESTAMP":"2020-12-18 07:52:52","VALUE":"402.00"},{"TIMESTAMP":"2020-12-18 07:56:02","VALUE":"404.00"},{"TIMESTAMP":"2020-12-18 07:59:12","VALUE":"403.00"},{"TIMESTAMP":"2020-12-18 08:02:22","VALUE":"401.00"},{"TIMESTAMP":"2020-12-18 08:05:32","VALUE":"467.00"},{"TIMESTAMP":"2020-12-18 08:11:52","VALUE":"402.00"},{"TIMESTAMP":"2020-12-18 08:15:02","VALUE":"403.00"},{"TIMESTAMP":"2020-12-18 08:18:12","VALUE":"402.00"},{"TIMESTAMP":"2020-12-18 08:21:22","VALUE":"403.00"},{"TIMESTAMP":"2020-12-18 08:24:32","VALUE":"436.00"},{"TIMESTAMP":"2020-12-18 08:27:42","VALUE":"434.00"},{"TIMESTAMP":"2020-12-18 08:30:52","VALUE":"427.00"},{"TIMESTAMP":"2020-12-18 08:34:02","VALUE":"423.00"},{"TIMESTAMP":"2020-12-18 08:37:12","VALUE":"415.00"},{"TIMESTAMP":"2020-12-18 08:40:22","VALUE":"419.00"},{"TIMESTAMP":"2020-12-18 08:43:32","VALUE":"432.00"},{"TIMESTAMP":"2020-12-18 08:46:42","VALUE":"444.00"},{"TIMESTAMP":"2020-12-18 08:49:52","VALUE":"452.00"},{"TIMESTAMP":"2020-12-18 08:53:02","VALUE":"473.00"},{"TIMESTAMP":"2020-12-18 08:56:12","VALUE":"489.00"},{"TIMESTAMP":"2020-12-18 08:59:22","VALUE":"490.00"},{"TIMESTAMP":"2020-12-18 09:02:32","VALUE":"502.00"},{"TIMESTAMP":"2020-12-18 09:05:42","VALUE":"510.00"},{"TIMESTAMP":"2020-12-18 09:08:52","VALUE":"516.00"},{"TIMESTAMP":"2020-12-18 09:12:02","VALUE":"525.00"},{"TIMESTAMP":"2020-12-18 09:15:12","VALUE":"529.00"},{"TIMESTAMP":"2020-12-18 09:18:22","VALUE":"526.00"},{"TIMESTAMP":"2020-12-18 09:21:33","VALUE":"536.00"},{"TIMESTAMP":"2020-12-18 09:24:43","VALUE":"548.00"},{"TIMESTAMP":"2020-12-18 09:27:53","VALUE":"542.00"},{"TIMESTAMP":"2020-12-18 09:31:03","VALUE":"535.00"},{"TIMESTAMP":"2020-12-18 09:34:13","VALUE":"534.00"},{"TIMESTAMP":"2020-12-18 09:37:23","VALUE":"540.00"},{"TIMESTAMP":"2020-12-18 09:40:33","VALUE":"549.00"},{"TIMESTAMP":"2020-12-18 09:43:43","VALUE":"525.00"},{"TIMESTAMP":"2020-12-18 09:46:53","VALUE":"499.00"},{"TIMESTAMP":"2020-12-18 09:50:03","VALUE":"504.00"},{"TIMESTAMP":"2020-12-18 09:53:13","VALUE":"527.00"},{"TIMESTAMP":"2020-12-18 09:56:23","VALUE":"522.00"},{"TIMESTAMP":"2020-12-18 09:59:33","VALUE":"501.00"},{"TIMESTAMP":"2020-12-18 10:02:43","VALUE":"478.00"},{"TIMESTAMP":"2020-12-18 10:05:53","VALUE":"484.00"},{"TIMESTAMP":"2020-12-18 10:09:03","VALUE":"498.00"},{"TIMESTAMP":"2020-12-18 10:12:13","VALUE":"522.00"}]} Man beachte die lange letzte Zeile.

4) Anschließend habe ich den workaround aktiviert:

Code Auswählen Erweitern

my $oldverbose = main::AttrVal("global","verbose","3");
main::fhem("attr global verbose 2");
main::Debug('get ' . $args[0] . ' - webchart ' . $from . ' ' . $to . ' ' . $device . ' ' . $duration . ' TIMESTAMP ' . $reading);
my $string = main::fhem('get ' . $args[0] . ' - webchart ' . $from . ' ' . $to . ' ' . $device . ' ' . $duration . ' TIMESTAMP ' . $reading);
main::fhem("attr global verbose " . $oldverbose);

5) und erhalte im Log:

Code Auswählen Erweitern

2020.12.18 10:33:49 1: DEBUG>get logdb - webchart 2020-12-18_06:33:49 2020-12-18_10:33:49 ESP_Easy_1 timerange TIMESTAMP PPM
2020.12.18 10:33:49 1: DEBUG>Hier gibt DbLog_Get an DbLog_chartQuery weiter
2020.12.18 10:33:49 1: DEBUG>Hier ist der Einstieg in DbLog_chartQuery
2020.12.18 10:33:50 1: DEBUG>Hier wird DbLog_chartQuery verlassen, so wie es sein sollte.

Ohne den workaround erreicht man mit global verbose=2 das gleiche, wie schon gesagt. Aber da entgehen einem im Log natürlich andere Informationen. Mit dem workaround wird zwar das Füllen der Log-Datei verhindert, aber dafür taucht halt das rote Fragezeichen neben Save Config in der FHEM Oberfläche auf.

Ich hoffe, das ist erstmal genug Info.

Beste Grüße
Franz

[DS_Starter]

Hallo Franz,

danke für die vielen Infos.
Also der Logeintrag

2020.12.18 10:15:26 3: get logdb - webchart 2020-12-18_06:15:26 2020-12-18_10:15:26 ESP_Easy_1 .....

wird definitiv nicht durch das DbLog Modul/Device gemacht. Zur besseren Identifizierung startet bei DbLog ein Eintrag grundsätzlich mit:

Code Auswählen Erweitern


DbLog - <Name des schreibenden Device> ....


z.B.

Code Auswählen Erweitern


2020.12.18 13:49:13.193 4: DbLog LogDB -> insert table fhemtest.history committed by autocommit


Du hast ja auch schon dein Debug an der richtigen Stelle ins DbLog eingtragen und wie du siehst, wird der Logeintrag
genau nach

Code Auswählen Erweitern


DEBUG>Hier wird DbLog_chartQuery verlassen


erzeugt. Und du wirst wahrscheinlich auch bemerkt haben, dass es in der DbLog-Routine keinen Aufruf mit "Log" oder "Log3" gibt.

Ich habe es mal versucht nachzustellen und habe bei mir in der Browser Kommandozeile folgendes ausgeführt:

Code Auswählen Erweitern


{ main::fhem ("get LogDB - webchart 2020-12-18_06:33:49 2020-12-18_10:33:49 ESP_Easy_1 timerange TIMESTAMP PPM") }


Damit erhalte ich diesen Logeintrag ebenfalls. Wenn man diesen Aufruf aber vereinfacht und schreibt statt dessen:

Code Auswählen Erweitern


{ main::CommandGet (undef, "LogDB - webchart 2020-12-18_06:33:49 2020-12-18_10:33:49 ESP_Easy_1 timerange TIMESTAMP PPM") }


ist der Logeintrag verschwunden. Ich hatte bisher keine Zeit (und auch keine Lust ) tiefer zu ergründen weshalb bei Verwendung von 'fhem ("...")' das aufgerufenen Statement + das Ergebnis ins Log eintragen wird, aber es scheint im Kern (fhem.pl) zu liegen. Vielleicht finde ich noch die Stelle.

Aber es ist dir vermutlich geholfen wenn du dein Script so umschreibst:

Code Auswählen Erweitern


my $string = main::CommandGet (undef, "$args[0] . ' - webchart ' . $from . ' ' . $to . ' ' . $device . ' ' . $duration . ' TIMESTAMP ' . $reading");


Hoffe ich habe mich nicht verschrieben 

Grüße,
Heiko

[alkazaa]

Danke Heiko, das ist die Lösung!

Habe jetzt gesehen, dass man das auch ohne die 99_fronthemUtils.pm in der FHEM Oberfläche nachvollziehen kann.
Mit

Code Auswählen Erweitern

get logdb - webchart 2020-12-18_06:33:49 2020-12-18_10:33:49 ESP_Easy_1 timerange TIMESTAMP PPM
in der FHEM Kommandozeile bekommt man den SQL response in einem pop-up Fenster, ohne weiteren output in die Logdatei.

Mit

Code Auswählen Erweitern

{fhem("get logdb - webchart 2020-12-18_06:33:49 2020-12-18_10:33:49 ESP_Easy_1 timerange TIMESTAMP PPM")}
in der FHEM Kommandozeile bekommt man den SQL response in einem pop-up Fenster, UND den gleichen response in die Logdatei geschrieben.

Mit

Code Auswählen Erweitern

{CommandGet(undef, "logdb - webchart 2020-12-18_06:33:49 2020-12-18_10:33:49 ESP_Easy_1 timerange TIMESTAMP PPM")}
schließlich ist es wie im 1. Fall: man bekommt den output im pop-up Fenster und nichts in der Logdatei.

Und im Programm-Kontext der 99_fronthemUtils.pm funktioniert es auch.

Nochmals Dank und beste Grüße
Franz

P.S.:
Der Logeintrag

Code Auswählen Erweitern

    2020.12.18 10:15:26 3: get logdb - webchart 2020-12-18_06:15:26 2020-12-18_10:15:26 ESP_Easy_1 ..... war durch ein weiteres von mir eingefügtes Debug() in 99_fronthemUtils.pm erzeugt worden. Hatte ich vergessen, explizit zu erwähnen.