Eventmonitor hat Probleme mit der fhem.log-Option

[frank]

zum testen nutze ich gerne den eventmonitor, um zu sehen, welche fehler in fhem.log auftauchen.
jetzt habe ich leider feststellen müssen, dass das log unvollständig übermittelt wird. es fehlen jeweils komplette einträge. und zwar immer wieder die selben, als würde irgendwie gefiltert werden.

hier mal 2 beispiele mit global verbose 1:

zb alle 2,5 minuten fehlt vom modul 77_UWZ (verbose=3):

Code Auswählen Erweitern

2016.08.30 09:29:06.524 3: UWZ Unwetterzentrale: Run.962 Done fetching data

modul 32_mailcheck (sowohl mit verbose=5 als auch ohne extra verbose. diese info wird allerdings durch ein debug-attr freigeschaltet):

Code Auswählen Erweitern

Sending: DONE
Sent 6 bytes
Read:   7 OK IDLE completed
Sending: 9 SELECT INBOX/fhem
Sent 21 bytes
Read:   * 12 EXISTS
        * 0 RECENT
        * FLAGS (\Answered \Flagged \Deleted \Seen \Draft)
        * OK [PERMANENTFLAGS (\Answered \Flagged \Draft \Deleted \Seen \*)] Unlimited
        * OK [UNSEEN 11] Message 11 is first unseen
        * OK [UIDNEXT 126] Predicted next UID
        * OK [UIDVALIDITY 1422744200] UIDs valid
        9 OK [READ-WRITE] SELECT completed
Sending: 10 IDLE
Sent 9 bytes
Read:   + idling


ein weiteres beispiel:

mit global verbose=3 und verbose=4 von 77_UWZ.pm fehlen sogar perl warnings inclusive stacktrace infos:

Code Auswählen Erweitern

2016.08.30 10:29:06.570 1: PERL WARNING: Wide character in print at fhem.pl line 845.
2016.08.30 10:29:06.592 3: CUL_HM set SwitchUP01 on-for-timer 30
2016.08.30 10:29:06.595 3: stacktrace:
2016.08.30 10:29:06.595 3:     main::__ANON__                      called by fhem.pl (844)
2016.08.30 10:29:06.596 3:     main::Log3                          called by ./FHEM/77_UWZ.pm (82)
2016.08.30 10:29:06.596 3:     main::UWZ_Log                       called by ./FHEM/77_UWZ.pm (879)
2016.08.30 10:29:06.596 3:     main::UWZ_Run                       called by FHEM/Blocking.pm (140)
2016.08.30 10:29:06.597 3:     main::BlockingStart                 called by FHEM/Blocking.pm (78)
2016.08.30 10:29:06.597 3:     main::BlockingCall                  called by ./FHEM/77_UWZ.pm (541)
2016.08.30 10:29:06.597 3:     main::UWZ_Start                     called by fhem.pl (2815)
2016.08.30 10:29:06.598 3:     main::HandleTimeout                 called by fhem.pl (601)
2016.08.30 10:29:06.570 4: UWZ Unwetterzentrale: Run.879 Warn_0_LongText: Trotz �rtlicher Schauer oder Gewitter sind die B�den weiterhin recht trocken. Bei $
2016.08.30 10:29:06.598 4: UWZ Unwetterzentrale: Run.882 Warn_0_ShortText: Bis Dienstag hohe bis sehr hohe Waldbrandgefahr.


zusätzlich wird hier auch ein notify nicht getriggert, dass normalerweise bei perl warnings eine lampe anschaltet:

Code Auswählen Erweitern

define n_perlWarning notify n_perlWarning:.*PERL.WARNING:.* set SwitchUP01 on-for-timer 30
attr n_perlWarning readLog 1

edit: nicht ganz richtig: im log sieht man, dass das licht (theoretisch) geschaltet wird. allerdings wird es in der realität nie eingeschaltet. funkprobleme können es nicht sein, denn es passiert nur mit dieser "gefilterten" warnung alle 2,5 minuten nicht. das notify wird also doch getriggert, aber die befehls ausführung muss irgendwo "versanden".

gruss frank

[rudolfkoenig]

Ich brauche ein Beispiel, was ich moeglich einfach nachvollziehen kann (bitte kein UWZ oder sonstige Fremdmodule), da bei mir es zu funktionieren scheint: Mehrzeiler und Stacktrace kommt im Browser an. Der Anhang wurde mit folgenden Befehlen getriggert:

Code Auswählen Erweitern

fhem> { Log 1, "Hallo" }
fhem> { Log 1, "Hallo\nWorld" }
fhem> attr global stacktrace   
fhem> { Log 1, "Hallo\nWorld\There" }


Dass ein notify auf "PERL WARNING" getriggert hat, kann ich mir nicht vorstellen: weder wollte ich sowas je einbauen, noch kann ich im Code dafuer Hinweise entdecken, noch konnte ich es reproduzieren.

[frank]

Ich brauche ein Beispiel, was ich moeglich einfach nachvollziehen kann (bitte kein UWZ oder sonstige Fremdmodule), da bei mir es zu funktionieren scheint: Mehrzeiler und Stacktrace kommt im Browser an. Der Anhang wurde mit folgenden Befehlen getriggert:

das funktioniert bei mir natürlich ebenfalls.
und die lampe brennt für 30 sekunden, wenn das notify nicht disabled ist. 

Code Auswählen Erweitern

2016.08.30 16:12:35.379 1 : Hallo
2016.08.30 16:12:48.159 1 : Hallo World
2016.08.30 16:12:54.904 3 : CUL_HM set SwitchUP01 on-for-timer 30
2016.08.30 16:12:54.877 1 : PERL WARNING: Unrecognized escape \T passed through at (eval 22799) line 1.
2016.08.30 16:12:54.907 3 : eval: { Log 1, "Hallo\nWorld\There" }
2016.08.30 16:12:54.907 3 : stacktrace:
2016.08.30 16:12:54.907 3 : main::__ANON__ called by (eval 22799) (1)
2016.08.30 16:12:54.908 3 : (eval) called by fhem.pl (1004)
2016.08.30 16:12:54.908 3 : main::AnalyzePerlCommand called by fhem.pl (1023)
2016.08.30 16:12:54.908 3 : main::AnalyzeCommand called by fhem.pl (952)
2016.08.30 16:12:54.908 3 : main::AnalyzeCommandChain called by ./FHEM/01_FHEMWEB.pm (2258)
2016.08.30 16:12:54.909 3 : main::FW_fC called by ./FHEM/01_FHEMWEB.pm (764)
2016.08.30 16:12:54.909 3 : main::FW_answerCall called by ./FHEM/01_FHEMWEB.pm (455)
2016.08.30 16:12:54.909 3 : main::FW_Read called by fhem.pl (3212)
2016.08.30 16:12:54.909 3 : main::CallFn called by fhem.pl (669)
2016.08.30 16:12:54.910 1 : Hallo WorldThere

ich vermute bei uwz einen zusammenhang mit blocking.pm.
was wäre denn, wenn im fork ins log geschrieben wird? vielleicht hast du für diesen fall auch ein einfaches beispiel.
ansonsten muss ich wohl mal auf "einfache" beispiele warten. ich frage mich nur wie ich das merken könnte, wenn es nicht funktioniert.

Dass ein notify auf "PERL WARNING" getriggert hat, kann ich mir nicht vorstellen: weder wollte ich sowas je einbauen, noch kann ich im Code dafuer Hinweise entdecken, noch konnte ich es reproduzieren.

ich habe mich einfach an die commandref von notify gehalten.
das funktioniert ja auch prima und ist nicht das thema. ich dachte nur dass es vielleicht ein guter hinweis zum finden des eigentlichen problems sein könnte.

attr readLog
Execute the notify for messages appearing in the FHEM Log. The device in this case is set to the notify itself, e.g. checking for the startup message looks like:

    define n notify n:.*Server.started.* { Log 1, "Really" }
    attr n readLog

meine definition vom notify steht ja oben, eigentlich wie das beispiel. am notify liegt es aber nicht, da ich es gerade disabled habe und das problem weiterhin besteht.

dieses notify feature aber bitte nicht ausbauen.

[frank]

vieleicht hilft dieses neue beispiel:

nach dem umzug von fritzbox auf pi habe ich noch ein paar FB_Mail() aufrufe in meiner config vergessen, die jetzt in fhem.log folgendes melden:

Code Auswählen Erweitern

sh: 1: /sbin/mailer: not found
2016.08.31 11:59:38.024 3: Mail sent to frank_heidrich@gmx.de

der eventmonitor zeigt allerdings nur die 2. zeile:

Code Auswählen Erweitern

2016.08.31 11:59:38.024 3 : Mail sent to frank_heidrich@gmx.de

[frank]

es ist wohl so, dass alle meldungen, die über STDERR ins fhem.log geschrieben werden, nicht im eventmonitor landen. dies betrifft die beispiele mailcheck-debug und der misslungene aufruf von FB_Mail(). ebenso verhält sich zb folgender befehl in der fhem eingabezeile:

Code Auswählen Erweitern

{system('ls abc.123')}
die erzeugte fehlermeldung erscheint nur im log und nicht im eventmonitor.

Code Auswählen Erweitern

ls: cannot access abc.123: No such file or directory

wäre es möglich diese meldungen auch auf den eventmonitor zu bekommen?

[rudolfkoenig]

Ich will nicht mit pty und Co anfangen, und die Logdatei pollen will ich auch nicht. Stdout/Stderr auf einem selbstgeoeffneten Socket zu legen ist mir z.Zt. in fhem.pl auch noch zu viel, wenn, dann sollte das ein Modul machen. Freiwillige? Weitere Ideen? Ist die Muehe ueberhaupt den Aufwand Wert? Meinungen dazu?

[Markus Bloch]

STDERR/STDOUT wird beim öffnen des aktuellen Logfiles via redirectStdinStdErr() fest auf das Logfile umgelenkt, damit man diese Meldungen überhaupt mitbekommt. Der Mechanismus um Logmeldungen im Event-Monitor zu bekommen ist aber auf einer höheren Ebene in der Funktion Log3() implementiert, wo alle Instanzen informiert werden, die sich für Logmeldungen interessieren (aktuell nur FHEMWEB mWn). Dadurch bekommt man alle Meldungen die mit Log3()/Log() generiert werden auch im Event-Monitor mit.

Alternativ-Vorschlag:

STDERR/STDOUT beim starten öffnen und den FD in %selectlist legen. Normal im Main-Loop auf "Daten" prüfen und diese mit Log() ins Log bzw. Event-Monitor schreiben?

Gruß
Markus

[justme1968]

ich glaube das geht nicht weil die datentrichtung nicht stimmt. stdout schreibt daten raus der fd ist nicht zum lesen. bei stderr ebenso.

gruss
  andre

[rudolfkoenig]

Deswegen braucht man ein pty, socket oder pipe. Pipe gefaellt mir am besten: ist am einfachsten, und muesste unter Windows auch funktionieren.

[Markus Bloch]

Ja stimmt, nicht gründlich genug nachgedacht

[justme1968]

das mit der pipe wäre vermutlich das einfachste.

als nachteil fällt mir ein das die daten dann alle einmal durch fhem müssen. könnte das performance folgen haben?

das wichtigere ist aber: es gibt module die kommunizieren schon per pipe mit einem geforkten prozess. biegen also z.b. stdin/stdout um. stderr bleiben und landen aktuell automatisch im fhem log. hier könnte es das potential für deadlocks geben wenn fhem alle drei fd selber managed.

die generelle frage wäre also: warum ist das überhaupt wichtig? sollte man fehlerzustände nicht so im jeweiligen modul behandeln das es nicht nötig ist selber ins log zu schauen und ein notify darauf zu machen? oder falls es um die entwicklung geht: warum reicht ein tail auf das fhem log nicht aus?

[frank]

das modul 77_UWZ nutzt blockingCall():

Code Auswählen Erweitern

    $hash->{helper}{RUNNING_PID} =
        BlockingCall(
            "UWZ_Run",          # callback worker task
            $name,              # name of the device
            "UWZ_Done",         # callback result method
            120,                # timeout seconds
            "UWZ_Aborted",      #  callback for abortion
            $hash );            # parameter for abortion

es sieht so aus als würden sämtliche logmeldungen, die in der funktion UWZ_Run generiert werden, nicht im eventmonitor landen. muss das im modul geändert werden, oder woanders? gibt es dazu eventuell richtlinien, die ich weitergeben könnte?
hier wird auch das angesprochene perl warning erzeugt (ebenfalls nicht im eventmoniotor), welches zwar mein warning-notify triggert, aber das zu schaltende licht nur virtuell im log schaltet aber nicht in der "realität".

die generelle frage wäre also: warum ist das überhaupt wichtig? sollte man fehlerzustände nicht so im jeweiligen modul behandeln das es nicht nötig ist selber ins log zu schauen und ein notify darauf zu machen? oder falls es um die entwicklung geht: warum reicht ein tail auf das fhem log nicht aus?

ich war eigentlich nur irritiert, dass im eventmonitor die option fhem.log existiert, aber in der realität mehr wie die hälfte des echten logs nicht angezeigt wurde. vor allem eben auch warnings. grundsätzlich finde ich die kombination von events und log in vielen fällen sehr hilfreich, um probleme zu identifizieren.

falls es schwierigkeiten macht, das log komplett darzustellen, würde ja eventuell schon ein fetter roter hinweis am button reichen, um zu wissen, dass eventuell nur logauszüge dargestellt werden können. denn gelegentlich gibt es hier schon tips, dass man nicht mehr ins log schauen müsste, da der eventmonitor das selbe bringt. wenn hier jemand logs zum verifizieren eines problems postet, müsste man zur zeit eigentlich nachfragen, welchen ursprung das log hat.

gruss frank

[justme1968]

die Log3 meldungen des child landen im log weil der filedescriptor weiter gegeben wird, der child prozess hat keinen zugriff auf die verbindung die es zwischen parent und web browser gibt um die meldungen anzuzeigen und das parent fhem bekommt davon nichts mit und kann es auch nicht im event monitor anzeigen.

wenn es nur darum geht im event monitor alles zu sehen: wie wäre es wenn das parent fhem genau wie tail das log einfach zusätzlich zum lesen öffnen und zurück liest statt in Log3 zusätzlich daten für den event monitor zu erzeugen?