[Tipp] logging/debugging neu erstellter Funktionen

[frober]

Da ich der "Verursacher" dieses Boards bin, gleich einmal einen Tipp:

Erstellt man eine neue Funktion möchte man auch prüfen, dass alles so funktioniert wie man es gerne hätte.

Dazu werden folgende Möglichkeiten in Fhem bereitgestellt:
https://wiki.fhem.de/wiki/DevelopmentModuleAPI#Logging

z.B.

Code: [Auswählen]

Log($verbose, $message);
Das Problem ist, wenn man die Reihenfolge der  Abläufe kontrollieren möchte, kann das schief gehen, da Fhem nur ein Prozess ist. D.h. die Ereignisse (auch Logs) werden nacheinander abgearbeitet. Dabei kann es vorkommen, das die gewünschte Reihenfolge im Logging nicht eingehalten wird.
Darüber bin ich bei meiner ersten myUtils-Funktion gestolpert.

Dank justme1968 habe ich bei mir eine Erinnerungslücke gefunden: 

Da ich den Code über mehrere Tage kontrollieren wollte, habe ich FileLog benutzt, um die Logs in einer Datei übersichtlich auswerten zu können. Hier kommt es unter Umständen dazu, dass die Reihenfolge verwürfelt wird. Die Alternative mit Log() wollte ich aus den genannten Gründen nicht benutzen.

Dank Hilfe des Forums (u.a. CoolTux, Beta-User) ist der folgende Workaroud entstanden. Ein großes Dankeschön dafür.

Folgende beide Subs in myUtils anlegen (kann in einer myUtils-Datei erfolgen):

Code: [Auswählen]

# Logdatei zum debuggen
#
# $file = name.log;
# debuglog("blabla",$file);

sub debuglog {
  my $myState = shift // return; #Beta-User: Perl defined-or
  my $file    = shift //  q{unnamed.log};
  my $fileName = "/opt/fhem/log/$file";
  if(open my $DATEI, q{>>}, $fileName) {
    print ($DATEI Zeitstempel()."$myState\n");
    return close ($DATEI);
  } else {
    return "Can't open $fileName: $!";
  }
  return;
}

Code: [Auswählen]

sub Zeitstempel()
{
  return strftime("%Y-%m-%d %H:%M:%S ", localtime());
}
Aufruf in der eigenen Sub:

Code: [Auswählen]

my $file = "name.log";      # kann weggelassen werden, dann wird sie als unnamed.log angelegt
debuglog(" Text: $var", $file);

Die Datei wird dann unter /fhem/log automatisch angelegt.

Wenn man nun ein Filelog-Device anlegt und deaktiviert, kann man die Logdatei direkt in der Weboberfläche ansehen.

Code: [Auswählen]

defmod log_Bewaesserung FileLog ./log/name.log xxx
attr log_Bewaesserung disable 1

Funktioniert der Code nach dem Debugging, möchte man evtl. das Logging wieder deaktivieren.
Dazu kann man die Zeilen löschen (empfehle ich nicht, evtl  möchte man den Code später erweitern/ändern) oder auskommentieren.
Sind viele Log-Zeilen vorhanden, ist dies aufwändig...

Einfacher ist es, das Logging schaltbar zu gestalten.
Dazu legen wir eine weiter Variable in der eigenen Sub an und passen die Log-Zeile etwas an:

Code: [Auswählen]

my $logging = 1  # es funktioniert 0/1, true/false
debuglog(" Text: $var", $file) if $logging;

Um nun das Logging abzuschalten, setzt man $logging auf 0.


Eine weiter Möglichkeit wäre, das Logging über ein Attribut im Device zu schalten.

Dazu legen wir im Device ein neues Attribut an:

Code: [Auswählen]

attr <DEVICE> userattr mydebuglog:0,1
Das Attribut kann dann einfach gesetzt werden.

Im der Sub ändern wir die Zuweisung der Variablen folgendermaßen:

Code: [Auswählen]

my $logging = AttrVal(<DEVICE>,'mydebuglog',1)



An die @Experten: falls es Verbesserungspotential gibt...

[justme1968]

sorry wenn ich nur mit einer blöden frage komme...

wenn man die Reihenfolge der  Abläufe kontrollieren möchte, kann das schief gehen

wie kann das schief gehen? fhem macht genau das was man sagt. genau in der reihenfolge in der man es gesagt hat. es wird weder etwas ausgelassen noch dazuerfunden und auch nichts in der reihenfolge verändert.

[frober]

sorry wenn ich nur mit einer blöden frage komme...
wie kann das schief gehen? fhem macht genau das was man sagt. genau in der reihenfolge in der man es gesagt hat. es wird weder etwas ausgelassen noch dazuerfunden und auch nichts in der reihenfolge verändert.

...es gibt keine blöden Fragen, nur blöd Antworten....

Wohl gemerkt, es war meine erste Funktion in myUtils => automatische Beregnung

Ich habe einfach vieles geloggt:
ReadingsVal, Berechnungen, setreading etc.
Im Fhemlog passte die Reihenfolge nicht, was mich verwirrte. Es wurde alles mit dem gleichen Zeitstempel geschrieben:
https://forum.fhem.de/index.php/topic,103229.msg977444.html#msg977444


Nachtrag: Da war wohl meine Erinnerung falsch, ich hatte FileLog für das Device benutzt und nicht Log(), da ich die Daten zusammen gefasst in einer Datei  wollte.
Danke, ich werde das oben anpassen.

[justme1968]

grundsätzlich kann man davon ausgehen das alles in der gleichen reihenfolge geschrieben wird wie es auch geloggt wird.

wenn man so viel bzw. so schnell loggt das alles den gleichen zeitstempel bekommt kann man in global das mseclog attribut setzen um zeit stempel mit höherer auflösung zu bekommen.

falls das auch nicht reichen sollte (was eher unwahrscheinlich ist) hilft es am anfang und am ende jeder routine das ins log zu schreiben. es gibt auch eine routine mit der man sich den aktuellen callstack holen kann um zu sehen was in welcher reihenfolge aufgerufen wurde.

auf eine eigene log routine auszuweichen musste ich nich nie.

[frober]

grundsätzlich kann man davon ausgehen das alles in der gleichen reihenfolge geschrieben wird wie es auch geloggt wird.

wenn man so viel bzw. so schnell loggt das alles den gleichen zeitstempel bekommt kann man in global das mseclog attribut setzen um zeit stempel mit höherer auflösung zu bekommen.

falls das auch nicht reichen sollte (was eher unwahrscheinlich ist) hilft es am anfang und am ende jeder routine das ins log zu schreiben. es gibt auch eine routine mit der man sich den aktuellen callstack holen kann um zu sehen was in welcher reihenfolge aufgerufen wurde.

auf eine eigene log routine auszuweichen musste ich nich nie.

Ich hatte meinen vorherigen Beitrag nochmals bearbeitet, vielleicht hast du das nicht mehr gelesen...
Meine Erinnerung war fehlerhaft, um es als Anfänger leichter zu haben, habe ich FileLog benutzt (alles leserlich(er) in einer eigenen Datei),  daher kamen die Verwürfelung der Reihenfolge.
Ich habe das Log über mehrere Tage beobachtet und das war für mich so einfacher.