Logfile: "Eigene Kennung"

Archiv Allgemeine Diskussion (2.x/3.x)
1

Um in einem Logfile schnell die eigenen Einträge von denen des Systems unterscheiden zu können und vor allem, um in einem Logfile schnell etwas zu finden bzw. über mehrere Logfiles suchen zu können, möchte ich bei Ausgabe ins Logfile eine eindeutige Kennung haben.

Mittels LogMessage ist das noch einigermassen einfach, weil man den Sender benutzen kann und relativ klar ist, welche Einträge in dieser Spalte des Logs sonst so vorkommen.

Anders ist es bei echo oder print_r im code.

Ich würde gerne bei jedem Script, das Ausgaben produziert, zuerst eine solche Kennung ausgeben, denn so kann man auch kurze Blöcke gut erkennen.

Gibt es da Empfehlungen/Erfahrungen (vielleicht auch vom Hersteller) über „do’s & don’ts“?

2

Ich bin mir nicht ganz sicher, ob ich deine Frage richtig verstehe, aber wenn du mit echo oder print_r Output erzeugst, dann können sich Scripte überschneiden und deine Meldungen sind „durcheinander“.

Wenn ich Wert auf eine „saubere“ Ausgabe im Logfile lege, dann bereite ich die Meldung selber auf.

if ($debug)
IPS_LogMessage(IPS_GetName($_IPS['SELF']), "--- Ausgabe ---
Wert 1 = ".$wert1."
Wert 2 = ".$wert2."
---
");

Das Ergbnis ist nicht „absolut super“, dann hätte man vor jeder Zeile den Datum/Script-Block, aber so kann man im Log auch herausfinden, was zusammengehört.

24.09.2012 22:56:07.890 |     0 | CUSTOM  | Meldungen            | --- Ausgabe ---
Wert 1 = 4711
Wert 2 = 4712
---

24.09.2012 ...

Damit kannst du dir beliebige Zeilen aufbauen und etsprechend das Logfile filtern ;).

Obwohl man den Teil "24.09.2012 22:56:07.890 | 0 | CUSTOM | Meldungen | " ja auch selber erzeugen könnte, wenn man ihn denn unbedingt sehen möchte.

3

Dass man seine Ausgabe mit IPS_LogMessage aufbereiten kann, ist klar.

aber wenn du mit echo oder print_r Output erzeugst, dann können sich Scripte überschneiden und deine Meldungen sind „durcheinander“.

Das sehe ich eben gerade anders.

Meine Test haben ergeben, dass alle Ausgaben per echo und print_r(), die ein Script macht, von IPS gesammelt und dann nach Beendigung komplett und an einem Stück ins Log geschrieben werden. --> KEINE Überschneidungen

Mit IPS_LogMessage() geschriebene Logs werden „zeitgerecht“ ins Log geschrieben und liegen daher potenziell verstreut (siehe Beispiele am Ende dieses Posts).

Genau deshalb will ich ja auch mit diesem Mittel ( print_r() ) arbeiten, um für einen Scriptablauf ein mehrzeiliges Summary zu schreiben, während ich mit IPS_LogMessage nur noch bestimmt Einzelmeldungen absetze, wenn es im Gesamtkontext auf die Zeit ankommt denn bei diesen (!) Einträgen kann es im Log durcheinander gehen.

So, jetzt zurück zu meiner Frage:

Gibt es Hinweise / Tipps, was man NICHT in die Ausgabe per echo oder print_r() in das Logfile schreiben sollte?

Gibt es Hinweise / Tipps, wie man diese Ausgabenam besten strukturiert?

Nachfolgend noch die Scripte. Im Script 0 habe ich das sleep() vor dem Aufruf des zweiten Scripts übrigens gemacht, weil sonst mal das erste, mal das zweite zuerst gestartet wurde (laut Log).

Zum Testen:
Drei Miniscripte. Das Erste (#0) ruft die beiden anderen auf:
Script #0


echo "*****
**** run Two Scripts **
";
IPS_LogMessage( "S0" , "s0~~~~~#1");
$id1 = 56443; // id1
$id2 = 46629; // id2

IPS_LogMessage( "S0" , "s0~ call s1");
IPS_RunScript( $id1 );
IPS_LogMessage( "S0" , "s0~ call s2");
IPS_RunScript( $id2 );

echo "*****
**** END Two Scripts **
";
IPS_LogMessage( "S0" , "s0~~~~~#2");
return;

Script #1


echo "
**** START: S1 *********
";
IPS_LogMessage( "S1" , "s1~~~~~#1");
echo "DIESES IST S1 L1 ***************
";

ips_Sleep(5000);
IPS_LogMessage( "S1" , "s1~~~~~#2");
echo "DIESES IST S1 L2 ***************
";

return;

Script #2


echo "
**** START: S2 *********
";
IPS_LogMessage( "S2" , "s2~~~~~#1");

ips_Sleep(500);

echo "DIESES IST S2 L1 ***************
";
echo "DIESES IST S2 L2 ***************
";
ips_Sleep(5100);
echo "DIESES IST S2 L3 ***************
";
IPS_LogMessage( "S2" , "s2~~~~~#2");

return;

LOG:


29.09.2012 17:01:57.691 | 26499 | DEBUG   | ExecuteThreadID #3   | Skriptausführung: tests/t0.php ~ Absender: Execute
29.09.2012 17:01:57.691 |     0 | CUSTOM  | S0                   | s0~~~~~#1
29.09.2012 17:01:57.691 |     0 | CUSTOM  | S0                   | s0~ call s1
29.09.2012 17:01:57.691 | 56443 | DEBUG   | ExecuteThreadID #4   | Skriptausführung: tests/t1.php ~ Absender: RunScript
29.09.2012 17:01:57.692 |     0 | CUSTOM  | S1                   | s1~~~~~#1
29.09.2012 17:01:57.741 |     0 | CUSTOM  | S0                   | s0~ call s2
29.09.2012 17:01:57.741 | 46629 | DEBUG   | ExecuteThreadID #15  | Skriptausführung: tests/t2.php ~ Absender: RunScript
29.09.2012 17:01:57.741 |     0 | CUSTOM  | S0                   | s0~~~~~#2
29.09.2012 17:01:57.741 | 26499 | DEBUG   | ExecuteThreadID #3   | Ausgeführt, Resultat: 1, Erfolgreich: True, Zeit: 50 ms
29.09.2012 17:01:57.742 |     0 | CUSTOM  | S2                   | s2~~~~~#1
29.09.2012 17:02:02.692 |     0 | CUSTOM  | S1                   | s1~~~~~#2
29.09.2012 17:02:02.692 | 56443 | MESSAGE | ExecuteThreadID #4   | [00 ###### TEST & DEVELOP ongoing	1] = 
**** START: S1 *********
DIESES IST S1 L1 ***************
DIESES IST S1 L2 ***************

29.09.2012 17:02:02.692 | 56443 | DEBUG   | ExecuteThreadID #4   | Ausgeführt, Resultat: 1, Erfolgreich: True, Zeit: 5001 ms
29.09.2012 17:02:03.342 |     0 | CUSTOM  | S2                   | s2~~~~~#2
29.09.2012 17:02:03.342 | 46629 | MESSAGE | ExecuteThreadID #15  | [00 ###### TEST & DEVELOP ongoing	2] = 
**** START: S2 *********
DIESES IST S2 L1 ***************
DIESES IST S2 L2 ***************
DIESES IST S2 L3 ***************

29.09.2012 17:02:03.342 | 46629 | DEBUG   | ExecuteThreadID #15  | Ausgeführt, Resultat: 1, Erfolgreich: True, Zeit: 5601 ms