jb-alvarado
Anmeldungsdatum: 28. November 2012
Beiträge: 345
|
Hallo Allerseits,
ich bräuchte mal wieder einen Tipp. Ich würde gerne ein Logfile in Echtzeit überwachen und wenn ein bestimmter Eintrag auftaucht soll ein Befehl ausgelöst werden. Momentan schaut mein Ansatz so aus:
|
tail -fn0 $logFolder/air_0_$( date +%d-%m-%Y )_0900.log | awk '/RtpOutput -- skip/{
print "--------------------------------------------------------------------------------";
print system ("top -b -n 1 | head -n 13");
print " ";
print system ("iostat -m");
print "--------------------------------------------------------------------------------";
fflush()
}' >> $logFolder/windowsplay.log
|
Das gleiche habe ich auch schon mit einer while Schleife statt awk gemacht, aber war auch nicht zufriedenstellend. Das Problem dabei ist, dass awk nicht nur einmal auslöst, sondern mehrmals. Wie kann ich das hinbekommen, das wirklich nur beim neusten Treffer der Befehl einmal ausgeführt wird. Hatte noch einen Ansatz wo ich die Uhrzeit abfrage und mit dem Logeintrag vergleiche, aber das ganze soll so simple wie möglich laufen, ohne Systemaktivität zu verfälschen - möchte damit ein Prozess Debuggen. Hier mal der alte Versuch mit Zeitvergleich: 1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16 | awk '/RtpOutput -- skip/ {
lt=strftime("%F %T");
split($1,a,".");
split($2,b,":");
ft=mktime(a[3]" "a[2]" "a[1]" "b[1]" "b[2]" "int(b[3]));
gsub(/[-:]/," ",lt);
ct=mktime(lt)
} END {
if ( ct - ft <= 1 ) {
print "--------------------------------------------------------------------------------"
print system ("top -b -n 1 | head -n 13")
print ""
print system ("iostat -m")
print "--------------------------------------------------------------------------------"
}
}'
|
Bei der Methode würde es auch nicht reichen auf Sekunden zu runden, sondern ich bräuchte da Sekunden mit Nachkommastellen. Das Logfile baut sich in etwa so auf: 26.11.2016 09:00:00.068 (3864) ERROR: total frame read time is too long. Takes 42 ms
26.11.2016 09:00:00.068 (3864) (R,P,D): VIDEO(D,0,27) VANC(D,0,0) AUDIO0(D,0,15)
26.11.2016 09:00:20.797 (3880) ERROR: total frame read time is too long. Takes 771 ms
26.11.2016 09:00:20.797 (3880) (R,P,D): VIDEO(D,0,750) VANC(D,0,0) AUDIO0(D,0,21)
26.11.2016 09:00:38.098 (3864) ERROR: total frame read time is too long. Takes 73 ms
26.11.2016 09:00:38.098 (3864) (R,P,D): VIDEO(D,0,18) VANC(D,0,0) AUDIO0(D,0,55)
26.11.2016 09:33:05.299 (3760) PERF: RtpOutput -- skip 1 frame
26.11.2016 22:58:30.466 (3800) PERF: RtpOutput -- skip 1 frame
|
Seebär
Anmeldungsdatum: 2. Mai 2009
Beiträge: 829
|
Kenne awk nicht, aber Deine Wunsch ist doch: es kommt eine neue Zeile, und die soll ggf. verarbeitet werden, korrekt? Lässt sich z.B. so lösen:
a) ein Script welches das File überwacht ("watchdog") und b) neue Zeile an einen "worker" übergibt: watchdog.sh
| #!/bin/sh
datei=~/filetobewatched.log
if [ ! -f $datei ]; then
touch $datei
fi
tail -f --lines=0 $datei | ./worker.sh
|
worker.sh
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15 | #!/bin/sh
token="something to be searched"
echo "WatchDog"
while read line; do
if [[ $line == *$token* ]]
then
# BEISPIEL-Suche
# token von rechts suchen und es selbst und alles davor abschneiden. Dann bleibt der Rest rechts davon übrig.
myid=${line##*$token}
echo "myid $myid"
# hier dann weiter verarbeiten
fi
done
|
Wie du das token genau suchen und die Zeile parsen musst hängt natürlich von deinem Fall ab.
|
track
Anmeldungsdatum: 26. Juni 2008
Beiträge: 7174
Wohnort: Wolfen (S-A)
|
jb-alvarado schrieb: ich bräuchte mal wieder einen Tipp. Ich würde gerne ein Logfile in Echtzeit überwachen und wenn ein bestimmter Eintrag auftaucht soll ein Befehl ausgelöst werden.
Das hast Du ja mit dem tail -f und nachfolgendem Filter schon soweit sauber hingekriegt.
... Das Problem dabei ist, dass awk nicht nur einmal auslöst, sondern mehrmals. Wie kann ich das hinbekommen, das wirklich nur beim neusten Treffer der Befehl einmal ausgeführt wird.
Das ist der springende Punkt: wie soll der arme Filter wissen, was jetzt wirklich die letzte Zeile ist, in Echtzeit ? - denn es gibt ja jedes Mal wieder eine neue letzte Zeile - und klar: dann löst der Filter natürlich wieder aus. Da müsstest Du mal genauer definieren, wann Dein Filter auslösen soll. LG, track
|
jb-alvarado
(Themenstarter)
Anmeldungsdatum: 28. November 2012
Beiträge: 345
|
track schrieb: Das ist der springende Punkt: wie soll der arme Filter wissen, was jetzt wirklich die letzte Zeile ist, in Echtzeit ?
Von der Logik her einfach die letzte Zeile im Logfile ☺.
- denn es gibt ja jedes Mal wieder eine neue letzte Zeile - und klar: dann löst der Filter natürlich wieder aus.
Das wäre eigentlich in Ordnung, aber der Nachfolgende Befehl hat dann nicht mehr nur die letzten Zeile hergenommen, sondern es wurde der Befehl mehrmals gleichzeitig ausgeführt. Da müsstest Du mal genauer definieren, wann Dein Filter auslösen soll.
Mit Seebärs Ansatz scheint es jetzt zu gehen, verstehe nur nicht warum es dann nicht mit meinem Ansatz ging, der macht ja nichts anderes nur eben in einem Script. Von Ablauf her ist das so: In einer Windows VM läuft ein Programm was das Logfile schreibt. Auf dem Host gibt es nun manchmal Aktivitäten die einen Error in der VM auslösen. Um nun herauszufinden, welcher Prozess im Host dafür verantwortlich ist, möchte ich zum genauen Zeitpunkt des Errors ein Systemstatus haben. Davon erhoffe ich mir Informationen die mir erlauben den Fehler zu unterbinden. Wenn ich z.B. mit stress -c 8 einen Test mache, verursache ich damit auch einen Error. Nur Ram oder IO stressen hingegen bewirkt nichts dramatisches. Daher soll nun das Logfile gelesen werden, und wenn der Fehler: RtpOutput – skip auftaucht, soll so schnell wie möglich ein Systemstatus geloggt werden. Das mache ich mit top -b -n 1 und iostat -m. Bei meinen alten Versuche wurde nun öfters ein Systemstatus gemacht, als im Log verzeichnet wurde. Dadurch wird der Status natürlich unbrauchbar.
|
Seebär
Anmeldungsdatum: 2. Mai 2009
Beiträge: 829
|
jb-alvarado schrieb: track schrieb:
Mit Seebärs Ansatz scheint es jetzt zu gehen...
Fein. Wobei ich das nie mit Masse probiert habe, k.A: also was passiert, wenn der Logger-Prozess da nun plötzlich 10.000 Zeilen reinloggt (dann sollte der watchdog 10.000x feuern und entsprechend viele Kindern aufrufen) und davon dann auch noch viele Treffer sind (und die dann wieder Last machen. Synchronisiert ist da auch nichts. Aber wenn's genügt ist ja gut.
|
jb-alvarado
(Themenstarter)
Anmeldungsdatum: 28. November 2012
Beiträge: 345
|
Seebär schrieb: Wobei ich das nie mit Masse probiert habe, k.A: also was passiert, wenn der Logger-Prozess da nun plötzlich 10.000 Zeilen reinloggt (dann sollte der watchdog 10.000x feuern und entsprechend viele Kindern aufrufen) und davon dann auch noch viele Treffer sind (und die dann wieder Last machen. Synchronisiert ist da auch nichts.
Das kann ich schon mal ausschließen. Das Maximum in der Sekunden kann 25 sein. Das Log mit den meisten Einträgen kommt bei 14 Stunden auf 766 Zeilen und 247 Treffer.
|
track
Anmeldungsdatum: 26. Juni 2008
Beiträge: 7174
Wohnort: Wolfen (S-A)
|
Was der ganzen Zauber mit den Zeitvergleichen bei awk soll, verstehe ich nicht ganz ... Es würde doch reichen, wenn Du einfach immer nur blind die letzte Zeile auswertest: | awk ' { t="" }
/RtpOutput -- skip/ { t=$1 " " $2 }
END { if(t!="") { print "------------------" t "--------------------------------------------"
print system ("top -b -n 1 | head -n 13")
print "" } }'
|
Wie gesagt, die Logik hatte ich nicht ganz verstanden, darum fragte ich. LG, track
|
jb-alvarado
(Themenstarter)
Anmeldungsdatum: 28. November 2012
Beiträge: 345
|
track schrieb: Was der ganzen Zauber mit den Zeitvergleichen bei awk soll, verstehe ich nicht ganz ...
Wie gesagt, das war mein erster Versuch, da hatte ich noch nicht mit tail gearbeitet, stattdessen eine while Schleife mit sleep 1 laufen lassen die immer wieder das Logfile neu einliest. Werde deinen Ansatz auch mal testen. Danke dafür!
Es würde doch reichen, wenn Du einfach immer nur blind die letzte Zeile auswertest: | awk ' { t="" }
/RtpOutput -- skip/ { t=$1 " " $2 }
END { if(t!="") { print "------------------" t "--------------------------------------------"
print system ("top -b -n 1 | head -n 13")
print "" } }'
|
Wie gesagt, die Logik hatte ich nicht ganz verstanden, darum fragte ich.
LG Jonathan
|
rklm
Projektleitung
Anmeldungsdatum: 16. Oktober 2011
Beiträge: 12834
|
jb-alvarado schrieb: track schrieb: Das ist der springende Punkt: wie soll der arme Filter wissen, was jetzt wirklich die letzte Zeile ist, in Echtzeit ?
Von der Logik her einfach die letzte Zeile im Logfile ☺.
Es gibt ja so lange keine letzte Zeile, wie der Schreiber nicht aufhört, in die Datei zu schreiben. Man weiß halt nicht, was noch kommt.
- denn es gibt ja jedes Mal wieder eine neue letzte Zeile - und klar: dann löst der Filter natürlich wieder aus.
Das wäre eigentlich in Ordnung, aber der Nachfolgende Befehl hat dann nicht mehr nur die letzten Zeile hergenommen, sondern es wurde der Befehl mehrmals gleichzeitig ausgeführt.
Vielleicht tritt der Fehler gleich mehrfach hintereinander auf?
In einer Windows VM läuft ein Programm was das Logfile schreibt. Auf dem Host gibt es nun manchmal Aktivitäten die einen Error in der VM auslösen. Um nun herauszufinden, welcher Prozess im Host dafür verantwortlich ist, möchte ich zum genauen Zeitpunkt des Errors ein Systemstatus haben. Davon erhoffe ich mir Informationen die mir erlauben den Fehler zu unterbinden.
Aber warum willst Du dann nicht jedes Mal den Systemstatus ermitteln, wenn der Fehler auftritt? Das gibt Dir doch viel mehr Informationen, als wenn Du das künstlich auf das letzte Vorkommen beschränkst.
Daher soll nun das Logfile gelesen werden, und wenn der Fehler: RtpOutput – skip auftaucht, soll so schnell wie möglich ein Systemstatus geloggt werden. Das mache ich mit top -b -n 1 und iostat -m. Bei meinen alten Versuche wurde nun öfters ein Systemstatus gemacht, als im Log verzeichnet wurde. Dadurch wird der Status natürlich unbrauchbar.
Das wäre unlogisch, denn der tail füttert ja jede Zeile des Logfiles nur ein Mal an awk weiter (ich beziehe mich auf den ersten Code, den Du gepostet hast). Wie soll das zustande kommen, dass es mehr Systemstati gibt als Zeilen mit Deinem Suchmuster im Logfile?
|
jb-alvarado
(Themenstarter)
Anmeldungsdatum: 28. November 2012
Beiträge: 345
|
rklm schrieb: Vielleicht tritt der Fehler gleich mehrfach hintereinander auf?
Ja das tut er auch, mehr dazu etwas weiter unten.
Aber warum willst Du dann nicht jedes Mal den Systemstatus ermitteln, wenn der Fehler auftritt? Das gibt Dir doch viel mehr Informationen, als wenn Du das künstlich auf das letzte Vorkommen beschränkst.
Doch das möchte ich auch.
Das wäre unlogisch, denn der tail füttert ja jede Zeile des Logfiles nur ein Mal an awk weiter (ich beziehe mich auf den ersten Code, den Du gepostet hast). Wie soll das zustande kommen, dass es mehr Systemstati gibt als Zeilen mit Deinem Suchmuster im Logfile?
Das verstehe ich auch noch nicht... Wenn ich den Code von ganz Oben nehme und laufen lasse passiert folgendes: Ich stresse die CPU vom Host für eine Sekunden. Im Logfile der VM entstehen 12 Fehlermeldungen die für mich relevant sind, es sind ein paar mehr aber ich möchte nur die auswerten die einen skip verursachen. Im Logfile was ich nun mit tail und awk schreibe habe ich hingegen über 300 Einträge. Im Terminal wo ich das Script ausführe bekomme ich auch die Meldung mehrmals: tail: /home/user/winlogs/air_0_28-11-2016_0900.log: Datei abgeschnitten Meine Ausgabe von top scheint auch noch nicht ganz zu funktionieren. Nirgends taucht stress auf. Edit: nehme jetzt statt top den Befehl: ps -Ao comm,pcpu,pri,ni --sort=-pcpu | head -n 8 Der ist etwas besser geeignet.
|
rklm
Projektleitung
Anmeldungsdatum: 16. Oktober 2011
Beiträge: 12834
|
jb-alvarado schrieb:
Im Logfile was ich nun mit tail und awk schreibe habe ich hingegen über 300 Einträge. Im Terminal wo ich das Script ausführe bekomme ich auch die Meldung mehrmals: tail: /home/user/winlogs/air_0_28-11-2016_0900.log: Datei abgeschnitten
Oh, das liegt dann daran, wie in die Datei geschrieben wird: Offensichtlich wird die Datei während des Schreibens abgeschnitten, so dass am Ende weniger Einträge sichtbar sind als tatsächlich geschrieben wurden. Möglicherweise hast Du zwei Prozesse, die in die Datei schreiben und die sich ins Gehege kommen. Demonstration: mit der Datei "x": | for ((i=0; i<10; ++i)); do
echo $i
sleep 1
done >log
echo >|log
for ((i=10; i<20; ++i)); do
echo $i
sleep 1
done >>log
|
ergibt sich 1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40 | $ bash x &
[1] 9132
$ tail -f log
0
1
2
3
4
5
6
7
8
9
tail: log: file truncated
10
11
12
13
14
15
16
17
18
19
[1]+ Done bash x
$ cat log
10
11
12
13
14
15
16
17
18
19
$
|
|
jb-alvarado
(Themenstarter)
Anmeldungsdatum: 28. November 2012
Beiträge: 345
|
rklm schrieb:
Oh, das liegt dann daran, wie in die Datei geschrieben wird: Offensichtlich wird die Datei während des Schreibens abgeschnitten, so dass am Ende weniger Einträge sichtbar sind als tatsächlich geschrieben wurden. Möglicherweise hast Du zwei Prozesse, die in die Datei schreiben und die sich ins Gehege kommen.
Hm, das ist natürlich blöd... Da habe ich keinen Einfluss drauf. Danke für die Erklärung! Mit meinem Experiment bin ich auch soweit durch. Zwar nicht viel Aufschluss daraus bekommen, wie ich wollte, aber ok...
|
rklm
Projektleitung
Anmeldungsdatum: 16. Oktober 2011
Beiträge: 12834
|
jb-alvarado schrieb:
Hm, das ist natürlich blöd... Da habe ich keinen Einfluss drauf. Danke für die Erklärung!
Bitte sehr.
Mit meinem Experiment bin ich auch soweit durch. Zwar nicht viel Aufschluss daraus bekommen, wie ich wollte, aber ok...
Du könntest das noch etwas weiter untersuchen, um herauszufinden, was da wirklich passiert. Du könntest z.B. mit inotifywatch nachschauen, welche IO-Aktionen auf der Datei von welchen Prozessen vorgenommen werden. Vielleicht ist es ja sogar ein Bug oder Du startest versehentlich zwei Instanzen.
|
jb-alvarado
(Themenstarter)
Anmeldungsdatum: 28. November 2012
Beiträge: 345
|
rklm schrieb:
Du könntest das noch etwas weiter untersuchen, um herauszufinden, was da wirklich passiert. Du könntest z.B. mit inotifywatch nachschauen, welche IO-Aktionen auf der Datei von welchen Prozessen vorgenommen werden. Vielleicht ist es ja sogar ein Bug oder Du startest versehentlich zwei Instanzen.
Ich glaube iotifywatch bringt da nicht viel. Das zu überwachende Logfile wird ja von einem Windowsprogramm geschrieben - habe nur über cifs den Ordner gemountet um auf dem Ubuntu Host die Aktivitäten zu kontrollieren. Ich habe mir heute auch die Mühe gemacht, das System parallel zu tal -F ... zu beobachten, also einfach top laufen lassen und watch -n1 'ps -Ao comm,pcpu,pri,ni --sort=-pcpu | head -n 13'. Beim auslösen eines skips im Logfile gab es keinen sichtbaren Prozess der rein gefunkt hätte. Daher bringt es jetzt nichts, das ursprüngliche Script weiter zu verfeinern. Habe jetzt noch zwei drei Optimierungsoptionen die ich durchprobieren kann, wenn das nicht klappt gebe ich's erst mal auf.
|