staging.inyokaproject.org

Ich bastele ja schon seit einiger Zeit an einem lokalen (Instant Webserver) Server. Grundsätzlich (minimal) funktioniert der auch schon. Zum Debugging erzeuge ich dazu einige Ausgaben. Jeder Ausgabenzeile ist die Prozess-ID vorangestellt. Soweit so gut.

Da ein ordentlicher Server aber mehrere Anfragen gleichzeitig bearbeiten kann, ergibt sich daraus ein kleines Problem. Die Ausgaben erscheinen durcheinander. Hier mal ein Beispiel (Ausschnitt):

( 3730) GET /$THUMB/a42d21f29d40e9b7f9312db670e97152.png HTTP/1.1
( 3730) Host: 127.0.0.1:8080
( 3729) GET /$THUMB/020c8c2395320d992a3ae6f362eb3c7d.png HTTP/1.1
( 3729) Host: 127.0.0.1:8080
( 3730) User-Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/113.0
( 3730) Accept: image/avif,image/webp,*/*
( 3730) Accept-Language: de,en-US;q=0.7,en;q=0.3
( 3729) User-Agent: Mozilla/5.0 (X11; Ubuntu; Linux x86_64; rv:109.0) Gecko/20100101 Firefox/113.0
( 3730) Accept-Encoding: gzip, deflate, br
( 3729) Accept: image/avif,image/webp,*/*
( 3730) DNT: 1
( 3730) Connection: keep-alive
( 3729) Accept-Language: de,en-US;q=0.7,en;q=0.3
( 3730) Referer: http://127.0.0.1:8080/
( 3729) Accept-Encoding: gzip, deflate, br
( 3730) Sec-Fetch-Dest: image
( 3729) DNT: 1
( 3730) Sec-Fetch-Mode: no-cors
( 3729) Connection: keep-alive
( 3730) Sec-Fetch-Site: same-origin
( 3730) --------
( 3729) Referer: http://127.0.0.1:8080/
( 3730) HTTP/1.1 200 OK
( 3730) Date: Sat, 30 Aug 2025 15:10:38 GMT
( 3730) Server: ifserver 0.4
( 3729) Sec-Fetch-Dest: image
( 3730) Last-Modified: Tue, 27 May 2025 21:02:02 GMT
( 3730) Accept-Ranges: none
( 3730) Content-Length: 75914
( 3730) Connection: keep-alive
( 3730) keep-alive: timeout=10, max=200
( 3730) Content-Type: image/png
( 3730) 
( 3729) Sec-Fetch-Mode: no-cors
( 3730) Header size: 250
...

Man sieht, dass die Ausgaben der verschiedenen Prozesse durcheinander kommen. Die Frage ist jetzt, sollte oder könnte man die Ausgaben der verschiedenen Prozesse irgendwie zusammenfassen, so das es besser lesbar ist? Und wenn ja, wie kann man das umsetzen? Momentan verwende ich dafür einfache printf() Anweisung.

p.s.: die Prozesse werden per fork() erzeugt (falls das wichtig ist).

@Duakan: Ich würde sagen das ist keine Frage wie protokolliert wird, denn ”zusammenfassen” würde ja bedeuten man muss im Programm irgendwie anfangen Logmeldungen zu sammeln und damit aufzuhalten. Gerade zur Fehlersuche will man ja aber diese Informationen so schnell wie möglich raus schreiben, damit bei Problemen nicht irgendwas mit dem Server oder einem Prozess zusammen stirbt, was noch nicht raus geschrieben wurde weil ein anderer Worker noch nicht alle seine zusammengehörenden Logeinträge losgeworden ist.

Filtern und Gruppieren ist dann eher eine Aufgabe für die Auswertung des Protokolls.

Filtern und Gruppieren ist dann eher eine Aufgabe für die Auswertung des Protokolls.

Oh, dann müsste ich die Ausgaben in eine Datei schreiben, um das gruppieren zu können. Dafür müsste ich wohl ein neues Programm erfinden.

Es gibt da zwei Probleme:

• wie ist die zeitliche Abfolge

• welche Anfragen + Antworten gehören wie zusammen

Dazu muss ich noch anmerken, dass ich die Ausgaben, aus denen ein HTTP Header zusammengestellt wird direkt ausgegeben werden, aber andererseits in einem Puffer gesammelt werden, um dann letztlich als gesammelter Block gesendet zu werden (um den Netzwerk traffic gerinf zu halten).

Ein übliches Verfahren ist, jede Anfrage mit einer Transaktions-ID auszustatten, die dann durch den gesamten Prozess durchzuschleifen und bei jeder Log-Ausgabe mit auszugeben. Dann kann man nachher dem Log sowohl den globalen zeitlichen Verlauf als auch den Verlauf einzelner Anfragen entnehmen.

Eine Transaktions-ID habe ich nicht, aber ich könnte einen Zeitstempel oder eine laufende Nummer pro Prozess einbauen.

Je Anfrage geht nicht gut, wenn eine Verbindung mehrfach wieder Verwendet wird. Bei Firefox habe ich bis zu 6 Verbindungen gleichzeitig gesehen, die zyklisch wieder verwendet werden.

Beim Zeitstempel ist allerdings die Frage, wie genau der sein muss. Wget gibt bei Downloads manchmal als Zeit 0 sec an.

@Dakuan: Wieso geht pro Anfrage nicht gut?

Das mit Zeitstempel und Genauigkeit und was wget damit zu tun hat, verstehe ich auch nicht. Zeitstempel wären in der Tat nützlich und auch irgendwie Standard in Protokollen, aber weniger um Anfragen zu identifizieren, sondern bei jeder Zeile/Meldung um den zeitlichen Ablauf auch innerhalb einer Abfrage nachvollziehen zu können, und gegebenenfalls auch Protokolle aus anderen Quellen, Beispielsweise von einem Client, zum Protokoll des Servers in Beziehung setzen zu können.

Ich wollte damit andeuten, dass man beim Zeitstempel wohl auch die Sekundenbruchteile mitnehmen muss, weil innerhalb einer Sekunde mehrere Aktionen stattfinden können. Ein Zähler wäre einfacher.

@Dakuan: Wieso geht pro Anfrage nicht gut?

Ich nehme die Behauptung zurück. Ich war von falschen Voraussetzungen ausgegangen.

Dakuan schrieb:

Eine Transaktions-ID habe ich nicht, aber ich könnte einen Zeitstempel oder eine laufende Nummer pro Prozess einbauen.

Zeitstempel ist unzuverlässig. Generiere lieber als UUID.

Je Anfrage geht nicht gut, wenn eine Verbindung mehrfach wieder Verwendet wird. Bei Firefox habe ich bis zu 6 Verbindungen gleichzeitig gesehen, die zyklisch wieder verwendet werden.

Das must Du Dir überlegen, ob Du eine Tx ID pro Verbindung oder pro Request oder beides haben willst.

Warum das Rad neu erfinden, wenn es schon seit Ewigkeiten rund läuft?

Schreibe die Meldungen doch ganz einfach mit logger ins Systemlog. Da kann man jede Menge Identifizierungsmerkmale mitgeben und Zeitstempel werden automatisch erzeugt.

Abfragen kann man mit journalctl, ggf. ergänzt durch grep.

logger kannte ich noch nicht. Aber das geht auch jetzt schon:

$ ifserver -- -d1 -v1 | logger

Das ergibt dann:

Sep 01 19:20:21 samurai manfred[8202]: ( 8207) Host: 127.0.0.1:8080
Sep 01 19:20:21 samurai manfred[8202]: ( 8205) Header size: 212
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) User-Agent: Dillo/3.0.5
Sep 01 19:20:21 samurai manfred[8202]: ( 8205) closing fd 4
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) Accept: image/png,image/*;q=0.8,*
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) Accept-Encoding: gzip, deflate
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) DNT: 1
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) Referer: http://127.0.0.1:8080/
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) Connection: close
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) --------
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) HTTP/1.1 200 OK
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) Date: Mon, 01 Sep 2025 17:20:21 G
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) Server: ifserver 0.4
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) Last-Modified: Sun, 29 Jun 2025 1
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) Accept-Ranges: none
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) Content-Length: 52700
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) Connection: close
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) Content-Type: image/png
Sep 01 19:20:21 samurai manfred[8202]: ( 8207)
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) Header size: 212
Sep 01 19:20:21 samurai manfred[8202]: ( 8207) closing fd 4
lines 992-1014/1014 (END)

@rklm Es wird wohl auf eine ID pro Request hinauslaufen. Die Verbindung habe ich ja über die Prozess-ID. Aber ich will es nicht zu kompliziert machen. Der Server läuft nicht ständig und soll normalerweise seinen Schnabel halten. Wie man an obiger Startzeile sieht, müssen die Ausgabe auch extra angefordert werden (-v1 -d1).