Log Ausgaben ohne Zeitstempel fehlen im Event-Monitor

[DeeSPe]

Habe ich evtl. was verpasst?
Das Verhalten war bis vor ein paar Tagen nicht so.

Besonders ärgerlich ist das für mich als Dev da ich so im Event-Monitor nicht mehr die Ausgaben (Problemhinweise) beim reload eines Moduls sehe.

Wie bekomme ich die Logs zurück?
Will nicht immer in die Log Datei gucken müssen, da ist die Information nämlich weiter vorhanden.

Gruß
Dan

[rudolfkoenig]

Log Ausgaben ohne Zeitstempel fehlen im Event-Monitor

Sagt mir nichts, bitte anders formulieren oder am besten mit einem Beispiel demonstrieren. Mir ist eine Aenderung in diesem Bereich nicht bewusst.

Besonders ärgerlich ist das für mich als Dev da ich so im Event-Monitor nicht mehr die Ausgaben (Problemhinweise) beim reload eines Moduls sehe.

Ich waere nie auf die Idee gekommen, als Entwickler da nach Fehler zu suchen. Ich empfehle die log Ausgabe direkt aus dem Terminal (mit attr global logfile -), da kann nichts schiefgehen.

[DeeSPe]

Code Auswählen Erweitern


2017.04.13 18:10:13 3: msg globalMsg: ID=1492099812.96748.1 TYPE=light ROUTE=w_Alarm_Lichter STATUS=OK PRIORITY=-1(Low) TITLE='' MSG=''
Use of uninitialized value $d in hash element at fhem.pl line 4036.
Use of uninitialized value $d in hash element at fhem.pl line 4036.
Use of uninitialized value $d in hash element at fhem.pl line 4036.
Use of uninitialized value $d in hash element at fhem.pl line 4036.
Use of uninitialized value $d in hash element at fhem.pl line 4036.
Use of uninitialized value $d in hash element at fhem.pl line 4036.
Use of uninitialized value $d in hash element at fhem.pl line 4036.
Use of uninitialized value $d in hash element at fhem.pl line 4036.
Use of uninitialized value $d in hash element at fhem.pl line 4036.
Use of uninitialized value $d in hash element at fhem.pl line 4036.
2017.04.13 18:10:56 3: Home: Found 2 matching presence devices of devspec "TYPE=PRESENCE" for resident "rr_Daniel"! Matching devices: "PRESENCE2_rr_Daniel,PRESENCE_rr_Daniel"

z.B.: Dieses "Use of uninitialized value $d in hash element at fhem.pl line 4036." fehlt mir.

Und alles was eben an Fehlermeldungen kommt.
Auch die "Subroutine HOMEMODE_DayTime redefined at ./FHEM/22_HOMEMODE.pm line 1890." fehlt mir beim Modul reload.

Gruß
Dan

[rudolfkoenig]

Liegt daran, dass FHEM das nicht abgefangen hat, und deswegen auch gar nicht "richtig" ins Log geschrieben wird (per Log3) sondern auf STDOUT/STDERR, was gluecklicherweise auch ins fhem-log umgeleitet ist. Habe z.Zt. auch keine Ahnung, wie man das abfangen koennte, bzw. warum die aktuelle Methode mit _WARN_ nicht greift. Kann dich aber troesten: das hat noch nie mit dem Eventmonitor funktioniert. Noch ein Grund, warum man sich als Entwickler nicht darauf verlassen sollte.

[Thorsten Pferdekaemper]

...also ich würde das sogar als Fehler betrachten, wenn sowas im Event Monitor landet.
Gruß,
   Thorsten

[DeeSPe]

...also ich würde das sogar als Fehler betrachten, wenn sowas im Event Monitor landet.
Gruß,
   Thorsten

Also bis vor ein paar Tagen war es bei mir immer so dass wenn im Event Monitor das Häkchen "FHEM log" gesetzt war, ich eben auch alles was im Log landete im Event Monitor sehen konnte. Auch die Warnungen wie "Subroutine ..... redefined at ...." und sogar die Perl Warnungen wenn man mal eine Funktion fehlerhaft hatte (z.B. fehlerhafter RegEx). All diese Warnungen konnte ich auf allen meinen FHEM Systemen immer sehen wenn parallel der Event Monitor offen stand und das Häkchen "FHEM log" gesetzt war.
Die erste Tage ist mir das gar nicht wirklich aufgefallen dass das jetzt nicht mehr zu sehen ist.
Ein paar Tage später musste ich dann doch mal in's Log gucken und da viel mir auf dass dort für 2-3 Funktionen eine Menge Perl Warnungen standen, die ich natürlich gerne im Event Monitor schon gesehen hätte.

Gruß
Dan

[rudolfkoenig]

@DeeSPe: daran hat sich nichts geaendert. Die Zeilen ohne Zeitstempel kommen per STDOUT/STDERR rein, und solche hast du im EventMonitor nie gesehen. Die mit Zeitstempel (inkl. PERL WARNING) solltest du weiterhin sehen.

Wie geschrieben, ich weiss nicht, warum man mit $SIG{__WARN__} nicht alle Perl Warnungen abfangen kann, wenn jemand das weiss, bitte melden.

[DeeSPe]

Ich habe nun mal eine Neuinstallation auf meinem Testsystem gewagt und siehe da, bei einem "reload 22_HOMEMODE" sehe ich auch die bekannten Ausgaben im Log/Event-Monitor wieder.

Code Auswählen Erweitern


2017.05.07 00:41:14 1 : PERL WARNING: Subroutine HOMEMODE_Initialize redefined at ./FHEM/22_HOMEMODE.pm line 28.
2017.05.07 00:41:14 1 : PERL WARNING: Subroutine HOMEMODE_Define redefined at ./FHEM/22_HOMEMODE.pm line 41.
2017.05.07 00:41:14 1 : PERL WARNING: Subroutine HOMEMODE_Undef redefined at ./FHEM/22_HOMEMODE.pm line 113.
2017.05.07 00:41:14 1 : PERL WARNING: Subroutine HOMEMODE_Notify redefined at ./FHEM/22_HOMEMODE.pm line 126.

Im Logfile sieht es genau so aus!

In meinem Live-System sehe ich diese Ausgaben im Event-Monitor mit angehaktem "FHEM Log" NICHT.
Im Logfile steht es nur so:

Code Auswählen Erweitern


Subroutine HOMEMODE_Initialize redefined at ./FHEM/22_HOMEMODE.pm line 28.
Subroutine HOMEMODE_Define redefined at ./FHEM/22_HOMEMODE.pm line 41.
Subroutine HOMEMODE_Undef redefined at ./FHEM/22_HOMEMODE.pm line 113.
Subroutine HOMEMODE_Notify redefined at ./FHEM/22_HOMEMODE.pm line 126.

Welches Attribut habe ich denn wo gesetzt dass das so gekommen ist?
Ich suche nun schon wirklich lange nach der Lösung, wurde aber bisher nicht fündig.

Gruß
Dan

[rudolfkoenig]

In meinem Live-System sehe ich diese Ausgaben im Event-Monitor mit angehaktem "FHEM Log" NICHT.

Kein Wunder, Meldungen im Log ohne Zeitstempel wurden nicht mit der FHEM Log3 Funktion ins FHEM-Log geschrieben (sondern z.Bsp. direkt via  STDOUT/STDERR) und deswegen werden sie auch nicht weitergeleitet

Welches Attribut habe ich denn wo gesetzt dass das so gekommen ist?

Ich kenne nicht so ein Attribut, die Meldungen ohne Zeitstempel zeigen, dass der $SIG{_WARN_} Handler/sub nicht aktiv ist. Evtl. hat das einer der Module zurueckgesetzt.

[rudolfkoenig]

Ich sehe gerade, das HTTPMOD und MODBUS den WARN Handler auf DEFAULT setzen.

[DeeSPe]

Ich sehe gerade, das HTTPMOD und MODBUS den WARN Handler auf DEFAULT setzen.

Okay, HTTPMOD verwende ich im Livesystem, im Testsystem nicht (mehr).
Habe jetzt mal ein HTTPMOD Device im Testsystem angelegt und sofort ist der Zustand wie im Livesystem.
Der Schuldige scheint also gefunden zu sein, danke für den Hinweis.

Gruß
Dan

EDIT: Habe gerade gesehen dass die Änderungen erst mit dem Commit vom 2.4. kamen, was sich mit der Entdeckung meinerseits decken würde. https://svn.fhem.de/trac/changeset/13877/

[StefanStrobel]

Hallo,

ich habe das bei Modbus und HTTPMOD um die Evaluation von Perl-Expressions aus Attributen von Anwendern herum gebaut.
Es gab immer wieder Beschwerden über Warnungs und die Ursache war sehr schwer zu finden.

Für solche Expressions (z.B. reading01Expr o.ä. bei HTTPMOD) mache ich nun:

Code Auswählen Erweitern


    $SIG{__WARN__} = sub { Log3 $name, 3, "$name: $context warning evaluating $eName, val=$val, expr $expr: @_"; };
    $result = eval($expr);
    $SIG{__WARN__} = 'DEFAULT';


Für bessere Ideen bin ich offen.
Am elegantesten wäre vermutlich eine Möglichkeit den Warning-Handler zu sicher und ihn nach meinem Eval wieder auf den vorigen Wert zu setzen.
geht das mit $old = $SIG{__WARN__}?

Gruss
   Stefan

[rudolfkoenig]

geht das mit $old = $SIG{__WARN__}?

Was spricht gegen testen?

[StefanStrobel]

habs gerade selbst getestet.
Abgesehen davon, dass $SIG{__WARN__} initial undefined ist, kann man den Wert einfach sichern und zurücksetzen.
Ich werde das entsprechend umbauen und einchecken, dann sollte es keinen mehr stören.

Gruss
   Stefan

[DeeSPe]

Hab gerade Stefans aktuelle Testversion laufen und meine vermissten Log/Event-Monitor Einträge sind wieder da!
Dank an Stefan und ganz besonderen Dank an Rudi, der Mal wieder top geholfen hat!

Gruß
Dan