8. Protokollierung
Eine der Stärken von HAProxy sind seine präzisen Protokolle. Sie bieten vermutlich die detailliertesten Informationen, die bei einem solchen Produkt verfügbar sind. Das ist bei der Fehlerbehebung in komplexen Umgebungen sehr wichtig. Zu den standardmäßig protokollierten Angaben gehören Client-Ports, Zeitmessungen der TCP/HTTP-Zustände, der genaue Stream-Zustand und die genaue Ursache bei der Beendigung, Angaben zu Entscheidungen über die Weiterleitung an einen Server und natürlich die Möglichkeit, beliebige Header zu erfassen.
Damit Administratoren schneller reagieren können, macht HAProxy interne wie externe Probleme deutlich sichtbar. Protokolle können gleichzeitig mit unterschiedlichen Stufenfiltern an verschiedene Ziele gesendet werden:
- globale Protokolle auf Prozessebene (Systemfehler, Start/Stopp usw.)
- Systemfehler und interne Fehler je Instanz (Ressourcenmangel, Programmfehler usw.)
- externe Probleme je Instanz (Server verfügbar/ausgefallen, maximale Verbindungszahl)
- Aktivitäten je Instanz (Clientverbindungen), entweder beim Aufbau oder bei der Beendigung.
- Steuerung der Protokollstufe je Anfrage, etwa http-request set-log-level silent if sensitive_request
Durch die Verteilung unterschiedlicher Protokollstufen auf verschiedene Protokollserver können mehrere Betriebsteams zusammenarbeiten und ihre Probleme möglichst schnell beheben. Beispielsweise kann das Systemteam systemweite Fehler überwachen, während das Anwendungsteam den Verfügbarkeitszustand seiner Server in Echtzeit beobachtet und das Sicherheitsteam Aktivitätsprotokolle mit einer Stunde Verzögerung auswertet.
8.1. Protokollstufen
TCP- und HTTP-Verbindungen können mit Datum, Uhrzeit, Quell-IP-Adresse, Zieladresse, Verbindungsdauer, Antwortzeiten, HTTP-Anfrage, HTTP-Statuscode, Anzahl übertragener Bytes, Umständen der Stream-Beendigung und sogar ausgetauschten Cookie-Werten protokolliert werden. Damit lassen sich beispielsweise Probleme eines bestimmten Nutzers verfolgen. Alle Meldungen können an bis zu zwei syslog-Server gesendet werden. Weitere Informationen zu Protokoll-Facilities stehen beim Schlüsselwort “log” in Abschnitt 4.2 .
8.2. Protokollformate
HAProxy unterstützt 5 Protokollformate. Mehrere Felder kommen in allen Formaten vor und werden in den folgenden Abschnitten erläutert. Einige können je nach Konfiguration leicht abweichen, da bestimmte Optionen eigene Kennzeichen verwenden. Folgende Formate werden unterstützt:
-
Das Standardformat ist sehr einfach und wird äußerst selten verwendet. Es liefert nur grundlegende Angaben zur eingehenden Verbindung zum Zeitpunkt ihrer Annahme: Quell-IP:Port, Ziel-IP:Port und Frontend-Name. Dieser Modus wird irgendwann entfallen und daher nur kurz beschrieben.
-
Das TCP-Format ist umfangreicher. Es wird durch “option tcplog” im Frontend aktiviert. HAProxy wartet dann gewöhnlich bis zum Verbindungsende, bevor es protokolliert. Das Format enthält wesentlich mehr Informationen, etwa Zeitmessungen, Verbindungszahlen und Warteschlangengröße. Für reine TCP-Proxys wird dieses Format empfohlen.
-
Das HTTP-Format ist für HTTP-Proxys am umfangreichsten. Es wird durch “option httplog” im Frontend aktiviert. Es enthält dieselben Angaben wie das TCP-Format, ergänzt um HTTP-spezifische Felder wie Anfrage, Statuscode sowie erfasste Header und Cookies. Für HTTP-Proxys wird dieses Format empfohlen.
-
Das CLF-HTTP-Format entspricht dem HTTP-Format, ordnet die Felder aber wie im CLF-Format an. In diesem Modus stehen alle Zeitmessungen, erfassten Werte, Flags usw. jeweils in einem eigenen Feld hinter den gemeinsamen Feldern, in derselben Reihenfolge wie im Standard-HTTP-Format.
-
Mit dem benutzerdefinierten Protokollformat lassen sich eigene Protokollzeilen gestalten.
Die folgenden Abschnitte beschreiben diese Formate im Einzelnen. Die Formatbeschreibung erfolgt feldweise. Sofern nicht anders angegeben, ist ein Feld ein Textabschnitt, der durch eine beliebige Anzahl von Leerzeichen abgegrenzt wird. Da syslog-Server am Zeilenanfang Felder einfügen können, wird stets angenommen, dass das erste Feld den Prozessnamen und die Prozesskennung enthält.
Hinweis: Da Protokollzeilen recht lang sein können, sind die Beispiele in den folgenden Abschnitten möglicherweise auf mehrere Zeilen aufgeteilt. Beispielzeilen beginnen mit 3 schließenden spitzen Klammern (’>>>’). Bei einer mehrzeiligen Darstellung endet jede nicht abschließende Zeile mit einem Backslash (’\’), und die nächste Zeile ist um zwei Zeichen eingerückt.
8.2.1. Standard-Protokollformat
Dieses Format wird verwendet, wenn keine besondere Option gesetzt ist. Die Meldung wird sofort bei Annahme der Verbindung ausgegeben. Derzeit ist dies das einzige Format, das die Ziel-IP-Adresse und die Zielports der Anfrage protokolliert.
Beispiel:
Feld Format Auszug aus dem obigen Beispiel
Ausführliche Feldbeschreibung:
- “source_ip” ist die IP-Adresse des Clients, der die Verbindung aufgebaut hat.
- “source_port” ist der TCP-Port des Clients, der die Verbindung aufgebaut hat.
- “destination_ip” ist die IP-Adresse, mit der sich der Client verbunden hat.
- “destination_port” ist der TCP-Port, mit dem sich der Client verbunden hat.
- “frontend_name” ist der Name des Frontends (oder Listeners), das die Verbindung angenommen und verarbeitet hat.
- “mode” ist der Betriebsmodus des Frontends (TCP oder HTTP).
Bei einem UNIX-Socket sind Quell- und Zieladresse als “unix:” gekennzeichnet. Die Ports geben die interne ID des Sockets an, der die Verbindung angenommen hat; dieselbe ID erscheint auch in den Statistiken.
Für neue Installationen wird von diesem veralteten Format abgeraten, da es irgendwann entfallen wird.
8.2.2. TCP-Protokollformat
Das TCP-Format wird durch “option tcplog” im Frontend verwendet und für reine TCP-Proxys empfohlen. Es liefert viele wertvolle Informationen zur Fehlerbehebung. Da es Zeitmessungen und Bytezähler enthält, wird die Meldung normalerweise am Sitzungsende ausgegeben. Mit “option logasap” kann sie früher ausgegeben werden, was in den meisten Umgebungen mit langen Sitzungen wie entfernten Terminals sinnvoll ist. Sitzungen, die den “monitor”-Regeln entsprechen, werden niemals protokolliert. Mit “option dontlognull” im Frontend können außerdem Meldungen für Sitzungen unterdrückt werden, in denen Client und Server keine Daten ausgetauscht haben. Bei “option dontlog-normal” im Frontend werden erfolgreiche Verbindungen nicht protokolliert.
Intern ist das TCP-Protokollformat als benutzerdefiniertes Format mit genau der folgenden Zeichenkette deklariert. Sie kann bei Bedarf auch als Grundlage für Erweiterungen dienen. Alternativ lässt sich die Variable HAPROXY_TCP_LOG_FMT verwenden. Die Verwendung beschreibt Abschnitt 8.2.6 „Benutzerdefiniertes Protokollformat“:
Das CLF-Protokollformat ist intern als benutzerdefiniertes Format mit genau dieser Zeichenkette deklariert:
Einige Felder können je nach Konfigurationsoption leicht abweichen. Sie sind unten mit einem Sternchen (’*’) hinter dem Feldnamen gekennzeichnet.
Beispiel:
Feld Format Auszug aus dem obigen Beispiel
Ausführliche Feldbeschreibung:
-
“client_ip” ist die IP-Adresse des Clients, der die TCP-Verbindung zu HAProxy aufgebaut hat. Wurde die Verbindung stattdessen über einen UNIX-Socket angenommen, ersetzt das Wort “unix” die IP-Adresse. Bei einem Socket mit “accept-proxy” und korrekt verwendetem PROXY-Protokoll oder mit “accept-netscaler-cip” und korrekt verwendetem NetScaler Client IP Insertion-Protokoll geben die Protokolle die Informationen der weitergeleiteten Verbindung wieder.
-
“client_port” ist der TCP-Port des Clients, der die Verbindung aufgebaut hat. Wurde sie über einen UNIX-Socket angenommen, steht hier stattdessen die ID des annehmenden Sockets, die auch in der Statistikschnittstelle erscheint.
-
“accept_date” ist der genaue Zeitpunkt, zu dem HAProxy die Verbindung empfangen hat. Er kann geringfügig vom im Netzwerk beobachteten Zeitpunkt abweichen, wenn die Verbindung im System-Backlog warten musste. Gewöhnlich entspricht er dem Zeitpunkt in den Protokollen vorgeschalteter Firewalls. Im HTTP-Modus wird accept_date auf den frühesten Zeitpunkt zurückgesetzt, zu dem die Verbindung eine neue Anfrage empfangen kann: bei HTTP/1 auf das Ende der vorherigen Antwort, bei HTTP/2 unmittelbar nach der vorherigen Anfrage.
-
“frontend_name” ist der Name des Frontends (oder Listeners), das die Verbindung angenommen und verarbeitet hat.
-
“backend_name” ist der Name des Backends (oder Listeners), das zur Verwaltung der Verbindung zum Server gewählt wurde. Wenn keine Umschaltregel angewendet wurde, entspricht es dem Frontend, was bei TCP-Anwendungen häufig der Fall ist.
-
“server_name” ist der Name des letzten Servers, an den die Verbindung gesendet wurde. Nach Verbindungsfehlern und einer Umverteilung kann er vom zuerst gewählten Server abweichen. Dieser Server gehört zum Backend, das die Anfrage verarbeitet hat. Wurde die Verbindung vor Erreichen eines Servers abgebrochen, steht statt des Servernamens “
<NOSRV>”. -
“Tw” ist die gesamte Wartezeit in den verschiedenen Warteschlangen in Millisekunden. Der Wert kann “-1” sein, wenn die Verbindung vor Erreichen der Warteschlange abgebrochen wurde. Weitere Einzelheiten stehen unten unter „Zeitmessungen“.
-
“Tc” ist die gesamte Wartezeit bis zum Verbindungsaufbau zum endgültigen Server in Millisekunden, einschließlich Wiederholungsversuchen. Der Wert kann “-1” sein, wenn die Verbindung abgebrochen wurde, bevor eine Verbindung zum Server hergestellt werden konnte. Weitere Einzelheiten stehen unten unter „Zeitmessungen“.
-
“Tt” ist die gesamte Zeit zwischen Annahme und letztem Schließen in Millisekunden. Sie umfasst alle Verarbeitungsschritte. Eine Ausnahme besteht bei “option logasap”: Dann endet die Zeitmessung mit der Protokollausgabe. Ein vorangestelltes ‘+’ zeigt in diesem Fall an, dass der endgültige Wert größer sein wird. Weitere Einzelheiten stehen unten unter „Zeitmessungen“.
-
“bytes_read” ist die Gesamtzahl der zum Zeitpunkt der Protokollausgabe vom Server an den Client übertragenen Bytes. Bei “option logasap” erhält der Wert ein vorangestelltes ‘+’, das auf einen möglicherweise größeren Endwert hinweist. Es handelt sich um einen 64-Bit-Zähler; Werkzeuge zur Protokollauswertung müssen ihn daher ohne Überlauf verarbeiten können.
-
“termination_state” beschreibt den Zustand der Sitzung bei ihrer Beendigung. Das Feld zeigt den Sitzungszustand, die Seite, die die Sitzung beendet hat, und den Grund dafür (Zeitüberschreitung, Fehler usw.). Normalerweise sollten die Flags “–” lauten. Dies bedeutet, dass eine der Seiten die Sitzung beendet hat und keine Daten mehr in den Puffern lagen. Weitere Einzelheiten stehen unten unter „Stream-Zustand bei der Trennung“.
-
“actconn” ist die Gesamtzahl gleichzeitiger Verbindungen im Prozess zum Zeitpunkt der Protokollierung der Sitzung. Sie hilft zu erkennen, wann systemseitige Grenzen je Prozess erreicht wurden. Liegt actconn etwa nahe bei 512, während mehrere Verbindungsfehler auftreten, begrenzt das System den Prozess wahrscheinlich auf 1024 Dateideskriptoren, die alle belegt sind. Zur Systemanpassung siehe Abschnitt 3 „Globaler Abschnitt“.
-
“feconn” ist die Gesamtzahl gleichzeitiger Verbindungen im Frontend zum Zeitpunkt der Protokollierung der Sitzung. Damit lassen sich der Ressourcenbedarf bei hoher Last abschätzen und das Erreichen von “maxconn” des Frontends erkennen. Große sprunghafte Anstiege deuten meistens auf einen Engpass bei den Backend-Servern hin, manchmal aber auch auf einen Denial-of-Service-Angriff.
-
“beconn” ist die Gesamtzahl gleichzeitiger Verbindungen, die das Backend zum Zeitpunkt der Protokollierung der Sitzung verwaltet. Dazu gehören alle gleichzeitig auf Servern aktiven sowie die in Warteschlangen wartenden Verbindungen. Damit lässt sich abschätzen, wie viele zusätzliche Server eine Anwendung bei hoher Last benötigt. Große sprunghafte Anstiege deuten meistens auf einen Engpass bei den Backend-Servern hin, manchmal aber auch auf einen Denial-of-Service-Angriff.
-
“srv_conn” ist die Gesamtzahl der zum Zeitpunkt der Protokollierung der Sitzung noch auf dem Server aktiven Verbindungen. Sie kann den konfigurierten Parameter “maxconn” des Servers niemals überschreiten. Liegt sie sehr häufig nahe bei oder genau auf “maxconn”, greift die Verkehrsregelung häufig ein. Dann ist entweder maxconn des Servers zu niedrig, oder es gibt zu wenige Server, um die Last mit optimaler Antwortzeit zu verarbeiten. Ist “srv_conn” nur bei einem Server hoch, hat dieser meist ein Problem, durch das die Verarbeitung von Verbindungen länger dauert als bei den anderen Servern.
-
“retries” ist die Zahl der Wiederholungsversuche beim Verbindungsaufbau zum Server in dieser Sitzung. Sie muss normalerweise null sein, außer wenn ein Server genau zum Zeitpunkt des Verbindungsversuchs gestoppt wird. Häufige Wiederholungsversuche deuten meist auf ein Netzwerkproblem zwischen HAProxy und dem Server oder einen falsch konfigurierten System-Backlog des Servers hin, der keine neuen Verbindungen aufnehmen kann. Ein optional vorangestelltes ‘+’ zeigt an, dass die Sitzung nach Erreichen der maximalen Anzahl von Wiederholungsversuchen beim ursprünglichen Server umverteilt wurde. Der protokollierte Servername bezeichnet dann den Server, an den die Verbindung umverteilt wurde, und nicht den ersten. Beide können beispielsweise bei Hashing dennoch identisch sein. Als Faustregel gilt daher: Steht vor der Anzahl der Wiederholungsversuche ein ‘+’, sollte sie nicht dem protokollierten Server zugerechnet werden.
-
“srv_queue” ist die Gesamtzahl der Anfragen, die vor dieser Anfrage in der Serverwarteschlange verarbeitet wurden. War die Anfrage nicht in der Serverwarteschlange, ist der Wert null. Die ungefähre Antwortzeit des Servers lässt sich abschätzen, indem die Wartezeit durch die Anzahl der Anfragen in der Warteschlange geteilt wird. Durchläuft eine Sitzung nach einer Umverteilung zwei Serverwarteschlangen, werden ihre Positionen addiert. Eine Anfrage sollte nur nach einer Umverteilung sowohl die Server- als auch die Backend-Warteschlange durchlaufen.
-
“backend_queue” ist die Gesamtzahl der Anfragen, die vor dieser Anfrage in der globalen Warteschlange des Backends verarbeitet wurden. War die Anfrage nicht in der globalen Warteschlange, ist der Wert null. Damit lässt sich die durchschnittliche Warteschlangenlänge abschätzen. Geteilt durch den Parameter “maxconn” eines Servers ergibt sie leicht die Anzahl fehlender Server. Nach einer Umverteilung kann eine Sitzung die Backend-Warteschlange zweimal durchlaufen; dann werden beide Positionen addiert. Eine Anfrage sollte nur nach einer Umverteilung sowohl die Server- als auch die Backend-Warteschlange durchlaufen.
8.2.3. HTTP-Protokollformat
Das HTTP-Format ist das vollständigste und für HTTP-Proxys am besten geeignete Format. Es wird durch “option httplog” im Frontend aktiviert. Es liefert dieselben Informationen wie das TCP-Format und zusätzlich HTTP-spezifische Angaben. Wie beim TCP-Format wird die Meldung gewöhnlich am Stream-Ende ausgegeben, außer wenn “option logasap” angegeben ist. Dies ist meist nur für Download-Websites sinnvoll. Ein Stream, der den “monitor”-Regeln entspricht, wird niemals protokolliert. Mit “option dontlognull” im Frontend können außerdem Streams von der Protokollierung ausgenommen werden, bei denen der Client keine Daten gesendet hat. Bei “option dontlog-normal” im Frontend werden erfolgreiche Verbindungen nicht protokolliert.
Intern ist das HTTP-Protokollformat als benutzerdefiniertes Format mit genau der folgenden Zeichenkette deklariert. Sie kann bei Bedarf auch als Grundlage für Erweiterungen dienen. Alternativ lässt sich die Variable HAPROXY_HTTP_LOG_FMT verwenden. Die Verwendung beschreibt Abschnitt 8.2.6 „Benutzerdefiniertes Protokollformat“:
Das CLF-Protokollformat ist intern als benutzerdefiniertes Format mit genau dieser Zeichenkette deklariert:
Die meisten Felder entsprechen denen des TCP-Protokolls, einige unterscheiden sich. Manche Felder können je nach Konfigurationsoption leicht abweichen. Sie sind unten mit einem Sternchen (’*’) hinter dem Feldnamen gekennzeichnet.
Beispiel:
Feld Format Auszug aus dem obigen Beispiel
Ausführliche Feldbeschreibung:
-
“client_ip” ist die IP-Adresse des Clients, der die TCP-Verbindung zu HAProxy aufgebaut hat. Wurde die Verbindung stattdessen über einen UNIX-Socket angenommen, ersetzt das Wort “unix” die IP-Adresse. Bei einem Socket mit “accept-proxy” und korrekt verwendetem PROXY-Protokoll oder mit “accept-netscaler-cip” und korrekt verwendetem NetScaler Client IP Insertion-Protokoll geben die Protokolle die Informationen der weitergeleiteten Verbindung wieder.
-
“client_port” ist der TCP-Port des Clients, der die Verbindung aufgebaut hat. Wurde sie über einen UNIX-Socket angenommen, steht hier stattdessen die ID des annehmenden Sockets, die auch in der Statistikschnittstelle erscheint.
-
“request_date” ist der genaue Zeitpunkt, zu dem HAProxy das erste Byte der HTTP-Anfrage empfangen hat (Protokollfeld %tr).
-
“frontend_name” ist der Name des Frontends (oder Listeners), das die Verbindung angenommen und verarbeitet hat.
-
“backend_name” ist der Name des Backends (oder Listeners), das zur Verwaltung der Verbindung zum Server gewählt wurde. Wenn keine Umschaltregel angewendet wurde, entspricht es dem Frontend.
-
“server_name” ist der Name des letzten Servers, an den die Verbindung gesendet wurde. Nach Verbindungsfehlern und einer Umverteilung kann er vom zuerst gewählten Server abweichen. Dieser Server gehört zum Backend, das die Anfrage verarbeitet hat. Wurde die Anfrage vor Erreichen eines Servers abgebrochen, steht statt des Servernamens “
<NOSRV>”. Hat das Statistiksubsystem die Anfrage abgefangen, steht dort stattdessen “<STATS>”. -
“TR” ist die gesamte Wartezeit in Millisekunden vom Empfang des ersten Bytes bis zur vollständigen HTTP-Anfrage des Clients, ohne Nachrichtenkörper. Der Wert kann “-1” sein, wenn die Verbindung vor Empfang der vollständigen Anfrage abgebrochen oder eine ungültige Anfrage empfangen wurde. Er sollte immer sehr klein sein, da eine Anfrage gewöhnlich in ein einziges Paket passt. Hohe Werte deuten meist auf Netzwerkprobleme zwischen Client und HAProxy oder auf von Hand eingegebene Anfragen hin. Weitere Einzelheiten stehen in Abschnitt 8.4 „Zeitmessungen“.
-
“Tw” ist die gesamte Wartezeit in den verschiedenen Warteschlangen in Millisekunden. Der Wert kann “-1” sein, wenn die Verbindung vor Erreichen der Warteschlange abgebrochen wurde. Weitere Einzelheiten stehen in Abschnitt 8.4 „Zeitmessungen“.
-
“Tc” ist die gesamte Wartezeit bis zum Verbindungsaufbau zum endgültigen Server in Millisekunden, einschließlich Wiederholungsversuchen. Der Wert kann “-1” sein, wenn die Anfrage abgebrochen wurde, bevor eine Verbindung hergestellt werden konnte. Weitere Einzelheiten stehen in Abschnitt 8.4 „Zeitmessungen“.
-
“Tr” ist die gesamte Wartezeit in Millisekunden, bis der Server eine vollständige HTTP-Antwort ohne Daten gesendet hat. Der Wert kann “-1” sein, wenn die Anfrage vor Empfang einer vollständigen Antwort abgebrochen wurde. Er entspricht gewöhnlich der Bearbeitungszeit des Servers für die Anfrage, kann aber durch die vom Client an den Server gesendete Datenmenge beeinflusst werden. Hohe Werte bei “GET”-Anfragen deuten meist auf einen überlasteten Server hin. Weitere Einzelheiten stehen in Abschnitt 8.4 „Zeitmessungen“.
-
“Ta” ist die Zeit, in der die Anfrage in HAProxy aktiv war: die gesamte Zeit in Millisekunden zwischen dem Empfang des ersten Anfragebytes und dem Senden des letzten Antwortbytes. Sie umfasst alle Verarbeitungsschritte außer Handshake (siehe Th) und Leerlaufzeit (siehe Ti). Eine Ausnahme besteht bei “option logasap”: Dann endet die Zeitmessung mit der Protokollausgabe. Ein vorangestelltes ‘+’ zeigt in diesem Fall an, dass der endgültige Wert größer sein wird. Weitere Einzelheiten stehen in Abschnitt 8.4 „Zeitmessungen“.
-
“status_code” ist der an den Client zurückgegebene HTTP-Statuscode. Er wird gewöhnlich vom Server gesetzt, kann aber auch von HAProxy stammen, wenn der Server nicht erreichbar ist oder HAProxy seine Antwort blockiert.
-
“bytes_read” ist die Gesamtzahl der zum Zeitpunkt der Protokollausgabe an den Client übertragenen Bytes, einschließlich HTTP-Headern. Bei “option logasap” erhält der Wert ein vorangestelltes ‘+’, das auf einen möglicherweise größeren Endwert hinweist. Es handelt sich um einen 64-Bit-Zähler; Werkzeuge zur Protokollauswertung müssen ihn daher ohne Überlauf verarbeiten können.
-
“captured_request_cookie” ist ein optionaler Eintrag im Format “name=value”, der anzeigt, dass der Client dieses Cookie in der Anfrage mitgesendet hat. Cookie-Name und maximale Länge werden mit “capture cookie” in der Frontend-Konfiguration festgelegt. Ist die Option nicht gesetzt, enthält das Feld einen einzelnen Bindestrich (’-’). Es kann nur ein Cookie erfasst werden. Damit wird gewöhnlich der Austausch von Sitzungs-IDs zwischen Client und Server verfolgt, um durch Anwendungsfehler verursachte Sitzungsverwechslungen zwischen Clients zu erkennen. Weitere Einzelheiten stehen unten unter „HTTP-Header und Cookies erfassen“.
-
“captured_response_cookie” ist ein optionaler Eintrag im Format “name=value”, der anzeigt, dass der Server mit seiner Antwort ein Cookie zurückgegeben hat. Cookie-Name und maximale Länge werden mit “capture cookie” in der Frontend-Konfiguration festgelegt. Ist die Option nicht gesetzt, enthält das Feld einen einzelnen Bindestrich (’-’). Es kann nur ein Cookie erfasst werden. Damit wird gewöhnlich der Austausch von Sitzungs-IDs zwischen Client und Server verfolgt, um durch Anwendungsfehler verursachte Sitzungsverwechslungen zwischen Clients zu erkennen. Weitere Einzelheiten stehen unten unter „HTTP-Header und Cookies erfassen“.
-
“termination_state” beschreibt den Zustand des Streams bei seiner Beendigung. Wie bei TCP-Protokollen zeigt das Feld den Stream-Zustand, die Seite, die den Stream beendet hat, und den Grund dafür (Zeitüberschreitung, Fehler usw.). Die letzten beiden Zeichen enthalten außerdem Angaben zu Persistenzaktionen an Cookies. Normalerweise sollten die Flags mit “–” beginnen. Dies bedeutet, dass eine der Seiten den Stream beendet hat und keine Daten mehr in den Puffern lagen. Weitere Einzelheiten stehen unten unter „Stream-Zustand bei der Trennung“.
-
“actconn” ist die Gesamtzahl gleichzeitiger Verbindungen im Prozess zum Zeitpunkt der Protokollierung des Streams. Sie hilft zu erkennen, wann systemseitige Grenzen je Prozess erreicht wurden. Liegt actconn etwa nahe bei 512 oder 1024, während mehrere Verbindungsfehler auftreten, begrenzt das System den Prozess wahrscheinlich auf 1024 Dateideskriptoren, die alle belegt sind. Zur Systemanpassung siehe Abschnitt 3 „Globaler Abschnitt“.
-
“feconn” ist die Gesamtzahl gleichzeitiger Verbindungen im Frontend zum Zeitpunkt der Protokollierung des Streams. Damit lassen sich der Ressourcenbedarf bei hoher Last abschätzen und das Erreichen von “maxconn” des Frontends erkennen. Große sprunghafte Anstiege deuten meistens auf einen Engpass bei den Backend-Servern hin, manchmal aber auch auf einen Denial-of-Service-Angriff.
-
“beconn” ist die Gesamtzahl gleichzeitiger Verbindungen, die das Backend zum Zeitpunkt der Protokollierung des Streams verwaltet. Dazu gehören alle gleichzeitig auf Servern aktiven sowie die in Warteschlangen wartenden Verbindungen. Damit lässt sich abschätzen, wie viele zusätzliche Server eine Anwendung bei hoher Last benötigt. Große sprunghafte Anstiege deuten meistens auf einen Engpass bei den Backend-Servern hin, manchmal aber auch auf einen Denial-of-Service-Angriff.
-
“srv_conn” ist die Gesamtzahl der zum Zeitpunkt der Protokollierung des Streams noch auf dem Server aktiven Verbindungen. Sie kann den konfigurierten Parameter “maxconn” des Servers niemals überschreiten. Liegt sie sehr häufig nahe bei oder genau auf “maxconn”, greift die Verkehrsregelung häufig ein. Dann ist entweder maxconn des Servers zu niedrig, oder es gibt zu wenige Server, um die Last mit optimaler Antwortzeit zu verarbeiten. Ist “srv_conn” nur bei einem Server hoch, hat dieser meist ein Problem, durch das die Verarbeitung von Anfragen länger dauert als bei den anderen Servern.
-
“retries” ist die Zahl der Wiederholungsversuche beim Verbindungsaufbau zum Server in diesem Stream. Sie muss normalerweise null sein, außer wenn ein Server genau zum Zeitpunkt des Verbindungsversuchs gestoppt wird. Häufige Wiederholungsversuche deuten meist auf ein Netzwerkproblem zwischen HAProxy und dem Server oder einen falsch konfigurierten System-Backlog des Servers hin, der keine neuen Verbindungen aufnehmen kann. Ein optional vorangestelltes ‘+’ zeigt an, dass der Stream nach Erreichen der maximalen Anzahl von Wiederholungsversuchen beim ursprünglichen Server umverteilt wurde. Der protokollierte Servername bezeichnet dann den Server, an den die Verbindung umverteilt wurde, und nicht den ersten. Beide können beispielsweise bei Hashing dennoch identisch sein. Als Faustregel gilt daher: Steht vor der Anzahl der Wiederholungsversuche ein ‘+’, sollte sie nicht dem protokollierten Server zugerechnet werden.
-
“srv_queue” ist die Gesamtzahl der Anfragen, die vor dieser Anfrage in der Serverwarteschlange verarbeitet wurden. War die Anfrage nicht in der Serverwarteschlange, ist der Wert null. Die ungefähre Antwortzeit des Servers lässt sich abschätzen, indem die Wartezeit durch die Anzahl der Anfragen in der Warteschlange geteilt wird. Durchläuft eine Sitzung nach einer Umverteilung zwei Serverwarteschlangen, werden ihre Positionen addiert. Eine Anfrage sollte nur nach einer Umverteilung sowohl die Server- als auch die Backend-Warteschlange durchlaufen.
-
“backend_queue” ist die Gesamtzahl der Anfragen, die vor dieser Anfrage in der globalen Warteschlange des Backends verarbeitet wurden. War die Anfrage nicht in der globalen Warteschlange, ist der Wert null. Damit lässt sich die durchschnittliche Warteschlangenlänge abschätzen. Geteilt durch den Parameter “maxconn” eines Servers ergibt sie leicht die Anzahl fehlender Server. Nach einer Umverteilung kann ein Stream die Backend-Warteschlange zweimal durchlaufen; dann werden beide Positionen addiert. Eine Anfrage sollte nur nach einer Umverteilung sowohl die Server- als auch die Backend-Warteschlange durchlaufen.
-
“captured_request_headers” ist die Liste der Anfrage-Header, die durch “capture request header” im Frontend erfasst wurden. Mehrere Header können erfasst werden; sie sind durch einen senkrechten Strich (’|’) getrennt. Ist keine Erfassung aktiviert, entfallen die geschweiften Klammern, wodurch sich die übrigen Felder verschieben. Dieses Feld kann Leerzeichen enthalten. Seine Verwendung erfordert daher einen ausgefeilteren Protokollparser als ohne das Feld. Weitere Einzelheiten stehen unten unter „HTTP-Header und Cookies erfassen“.
-
“captured_response_headers” ist die Liste der Antwort-Header, die durch “capture response header” im Frontend erfasst wurden. Mehrere Header können erfasst werden; sie sind durch einen senkrechten Strich (’|’) getrennt. Ist keine Erfassung aktiviert, entfallen die geschweiften Klammern, wodurch sich die übrigen Felder verschieben. Dieses Feld kann Leerzeichen enthalten. Seine Verwendung erfordert daher einen ausgefeilteren Protokollparser als ohne das Feld. Weitere Einzelheiten stehen unten unter „HTTP-Header und Cookies erfassen“.
-
“http_request” ist die vollständige HTTP-Anfragezeile mit Methode, Anfrage und HTTP-Versionszeichenkette. Nicht druckbare Zeichen werden kodiert (siehe unten „Nicht druckbare Zeichen“). Dies ist immer das letzte Feld. Es ist stets von Anführungszeichen umschlossen und das einzige Feld, das selbst Anführungszeichen enthalten kann. Neue Felder werden vor diesem Feld in das Protokollformat eingefügt. Ist die Anfrage sehr groß und passt nicht in den standardmäßigen syslog-Puffer (1024 Zeichen), kann das Feld abgeschnitten werden. Deshalb muss es immer das letzte Feld bleiben.
8.2.4. HTTPS-Protokollformat
Das HTTPS-Format eignet sich am besten für HTTP-Verbindungen über SSL. Es erweitert das HTTP-Format (siehe Abschnitt 8.2.3 ) um SSL-bezogene Informationen und wird durch “option httpslog” im Frontend aktiviert. Wie bei TCP und HTTP wird die Meldung gewöhnlich am Stream-Ende ausgegeben, außer wenn “option logasap” angegeben ist. Ein Stream, der den “monitor”-Regeln entspricht, wird niemals protokolliert. Mit “option dontlognull” im Frontend können außerdem Streams von der Protokollierung ausgenommen werden, bei denen der Client keine Daten gesendet hat. Bei “option dontlog-normal” im Frontend werden erfolgreiche Verbindungen nicht protokolliert.
Intern ist das HTTPS-Protokollformat als benutzerdefiniertes Format mit genau der folgenden Zeichenkette deklariert. Sie kann bei Bedarf auch als Grundlage für Erweiterungen dienen. Alternativ lässt sich die Variable HAPROXY_HTTPS_LOG_FMT verwenden. Die Verwendung beschreibt Abschnitt 8.2.6 „Benutzerdefiniertes Protokollformat“:
Dieses Format entspricht im Wesentlichen dem HTTP-Format (siehe Abschnitt 8.2.3 ), an das neue Felder angehängt werden. Diese neuen Felder (Zeilen 17 und 18) werden hier erläutert. Für die HTTP-Felder siehe den HTTP-Abschnitt.
Beispiel:
Feld Format Auszug aus dem obigen Beispiel
Ausführliche Feldbeschreibung:
-
“fc_err” ist der Verbindungsstatus auf der Frontend-Seite und entspricht dem Sample-Abruf “fc_err”. Weitere Informationen liefern die Beschreibungen der Sample-Abruffunktionen “fc_err” und “fc_err_str”.
-
“ssl_fc_err” ist der letzte Fehler des ersten SSL-Fehlerstapels, der aus Sicht des Frontends auf der Verbindung aufgetreten ist. Damit lassen sich beispielsweise Fehler beim SSL-Handshake erkennen. Wenn alles erfolgreich war, ist der Wert 0. Weitere Informationen stehen in der Beschreibung des Sample-Abrufs “ssl_fc_err”.
-
“ssl_c_err” ist der Status der Prüfung des Clientzertifikats. Der Handshake kann auch bei einem Prüfungsfehlercode ungleich null erfolgreich sein, wenn der Fehler ignoriert wird. Siehe den Sample-Abruf “ssl_c_err” und die Option “crt-ignore-err”.
-
“ssl_c_ca_err” ist der Status der Prüfung der Clientzertifikatskette. Der Handshake kann auch bei einem Prüfungsfehlercode ungleich null erfolgreich sein, wenn der Fehler ignoriert wird. Siehe den Sample-Abruf “ssl_c_ca_err” und die Option “ca-ignore-err”.
-
“ssl_fc_is_resumed” ist wahr, wenn die eingehende TLS-Sitzung über den zustandsbehafteten Cache oder ein zustandsloses Ticket wiederaufgenommen wurde. Eine TLS-Sitzung kann von mehreren Anfragen gemeinsam genutzt werden.
-
“ssl_fc_sni” ist die vom Client zur Zertifikatsauswahl übermittelte SNI (Server Name Indication). Sie entspricht gewöhnlich dem Hostnamen der ersten Anfrage einer Verbindung. Fehlt das Feld, hat der Client möglicherweise keine SNI gesendet. haproxy verwendet dann das Standardzertifikat oder weist bei strict-sni die Verbindung ab.
-
“ssl_version” ist die SSL-Version des Frontends.
-
“ssl_ciphers” ist der für die Verbindung verwendete SSL-Cipher.
8.2.5. Fehlerprotokollformat
Schlägt eine eingehende Verbindung wegen eines SSL-Handshakes oder eines ungültigen PROXY-Protokoll-Headers fehl, protokolliert HAProxy das Ereignis in einem kürzeren, festen Zeilenformat. Dies gilt nicht, wenn mit “error-log-format” ein eigenes Fehlerprotokollformat definiert wurde. Standardmäßig werden Meldungen mit der Stufe LOG_INFO ausgegeben. Ist im Backend “log-separate-errors” gesetzt, wird stattdessen LOG_ERR verwendet. Verbindungen ohne Datenaustausch, etwa Prüfanfragen, werden bei gesetzter Option “dontlognull” nicht protokolliert.
Das Standardformat sieht so aus:
Diese Felder liefern nur die grundlegenden Informationen zur Untersuchung fehlgeschlagener Verbindungen.
Mit der Direktive “error-log-format” wird das oben beschriebene ältere Format nicht mehr verwendet; alle Fehlerprotokollzeilen folgen dann dem definierten Format.
Es folgt ein Beispiel für ein recht vollständiges error-log-format. Es gibt Quelladresse und -port, den Zeitpunkt von accept() für die Verbindung, den Frontend-Namen, die Anzahl aktiver Verbindungen im Prozess und im betreffenden Frontend, die interne Fehlerkennung von haproxy für die Frontend-Verbindung, die hexadezimale OpenSSL-Fehlernummer (die zur vollständigen Dekodierung an “openssl errstr” übergeben werden kann), den Status der Extraktion des Clientzertifikats (0 bedeutet kein Fehler), den Status der Prüfung des Clientzertifikats anhand der CA (0 bedeutet kein Fehler), einen booleschen Wert für eine neue oder wiederaufgenommene Verbindung, die optionale Server Name Indication (SNI) des Clients sowie gegebenenfalls den SSL-Versionsnamen und die auf der Verbindung verwendeten SSL-Cipher aus. Fehler bei Backend-Verbindungen werden hier niemals gemeldet: Damit eine Backend-Verbindung fehlschlagen kann, muss sie bereits einen erfolgreich angelegten Stream durchlaufen haben. Sie erscheint deshalb im regulären Verkehrsprotokoll (siehe option httplog oder option httpslog).
8.2.6. Benutzerdefiniertes Protokollformat
Ursprünglich dienten benutzerdefinierte Protokollformate ausschließlich der Protokollierung. Weil sich damit aber bequem mehrere komplexe Ausdrücke zu einer Zeichenkette zusammensetzen lassen, wurden sie von vielen Direktiven übernommen, die zuvor nur eine Zeichenkette als Argument akzeptierten. Diese können nun auch eine solche Formatdefinition annehmen. Derartige Argumente heißen in diesem Dokument meist “<fmt>” und werden genau wie das hier beschriebene Argument der Direktive “log-format” definiert.
Reichen die Standardformate für die Protokollierung nicht aus, lassen sich neue Formate sehr genau festlegen. Ein Protokollformat von Grund auf zu erstellen ist nicht immer einfach. Deshalb wird dringend empfohlen, zunächst die vorhandenen Formate (“option tcplog”, “option httplog”, “option httpslog”) anzusehen, das am besten passende auszuwählen, seine entsprechende “log-format”-Zeichenkette zu kopieren und anzupassen.
Eine benutzerdefinierte Protokollformatdefinition ist aus Sicht der Konfiguration ein einziges Argument. Sie darf deshalb keine Leerzeichen oder Tabulatoren enthalten, außer wenn diese mit einem Backslash (’\’) maskiert werden oder die gesamte Definition in Anführungszeichen steht. Letzteres wird empfohlen. Formatzeichenketten ohne Anführungszeichen werden nicht mehr empfohlen: Die Erfahrung zeigt, dass sie sehr fehleranfällig sind, weil bereits ein fehlender Backslash das Format unbemerkt abschneiden kann. Solche Konfigurationen sind weiterhin häufig anzutreffen, weil Protokollformate nach Version 1.5-dev9 breit übernommen wurden, 3 Jahre bevor Anführungszeichen verwendbar waren. Es wird jedoch empfohlen, sie jetzt in Zeichenketten mit Anführungszeichen umzuwandeln und die Backslashes zu entfernen.
Eine Protokollformatdefinition besteht aus beliebig vielen Formatelementen, getrennt durch Text und Leerzeichen. Ein Formatelement beginnt mit ‘%’. Um ein wörtliches ‘%’ auszugeben, muss ihm ein weiteres ‘%’ vorangestellt werden, sodass ‘%%’ entsteht.
Formatelemente können Aliase oder Sample-Ausdrücke sein:
Steht ein Element in eckigen Klammern (’[’ .. ‘]’), wird es als Regel mit einem Sample-Ausdruck verwendet (siehe Abschnitt 7.3 ). Damit lassen sich seltenere Angaben ergänzen, etwa der DN des SSL-Clientzertifikats oder der Schlüssel, mit dem ein Eintrag in einer Stick Table gespeichert würde. Dies wird auch häufig bei Aktionen außerhalb der Protokollierung verwendet, etwa zur Header-Bearbeitung oder für Variablen.
Hat das Element dagegen einen alphanumerischen Namen, ist es ein Alias. Die verfügbaren Aliase stehen in der folgenden Tabelle.
Elemente können Argumente in geschweiften Klammern (’{}’) annehmen. Mehrere Argumente werden darin durch Kommas getrennt. Flags lassen sich mit einem vorangestellten ‘+’ oder ‘-’ hinzufügen oder entfernen. Die verfügbaren Flags werden weiter unten aufgeführt.
Der besondere Alias “%o” überträgt seine Flags auf alle anderen Formatelemente derselben Formatzeichenkette. Dies ist besonders bei Zeichenketten mit Anführungszeichen (“Q”) und maskierten Zeichen (“E”) praktisch.
Der besondere Alias “%OG” liefert den Ursprung einer Protokollmeldung, also wann und wo sie erzeugt wurde, in lesbarer Form. Das ist besonders bei “option logasap” nützlich: Einige Protokollvariablen oder Sample-Abrufe können unvollständige Werte liefern oder sich unterschiedlich verhalten, je nachdem, wann und wo der Formatausdruck ausgewertet wurde. Mögliche Werte sind:
- “sess_error”: Die Meldung wurde bei der Behandlung eines Sitzungsfehlers erzeugt.
- “sess_killed”: Die Meldung wurde beim Abbruch einer Sitzung erzeugt (beendete embryonale Sitzung).
- “txn_accept”: Die Meldung wurde unmittelbar nach Annahme der Frontend-Verbindung erzeugt.
- “txn_request”: Die Meldung wurde nach Empfang der Clientanfrage erzeugt.
- “txn_connect”: Die Meldung wurde nach Aufbau der Backend-Verbindung erzeugt.
- “txn_response”: Die Meldung wurde bei der Verarbeitung der Serverantwort erzeugt.
- “txn_close”: Die Meldung wurde im letzten Transaktionsschritt vor dem Schließen erzeugt.
- “unspec”: Unbekannt oder nicht angegeben. “%OG” ist nur bei der Protokollierung relevant.
Elemente können optional mit (’()’) benannt werden. Der Name muss unmittelbar nach ‘%’ vor den Argumenten stehen. Bei gesetztem Kodierungsflag wie “json” oder “cbor” wird er automatisch als Schlüsselname verwendet. Ohne Kodierungsflag, also standardmäßig, wird der Name ignoriert. Der Ausgabetyp eines Elements lässt sich durch ‘:type’ hinter dem Namen erzwingen: %(itemname:itemtype)aliasname oder %(itemname:itemtype)[expr], wobei itemtype ‘str’, ‘sint’ oder ‘bool’ sein kann. Die Typangabe ist nur bei Verwendung einer Kodierungsmethode relevant. Auch ein leerer Name ist möglich, um den Ausgabetyp eines anonymen Elements zu erzwingen: %(:itemtype), etwa wenn die Kodierung nicht global gesetzt ist. Weitere Informationen stehen unten bei den Flag-Definitionen.
Da benutzerdefinierte Protokollformate ursprünglich nur für die Protokollierung gedacht waren, werden nicht druckbare und unsichere Zeichen (außerhalb der ASCII-Codes 32 bis 126 sowie einige weitere) je nach Einsatzort gesondert behandelt. Abschnitt 8.6 beschreibt das genaue Vorgehen für Protokolle. Es verhindert die Ausgabe unsicherer Codes, die die Lesbarkeit im Terminal beeinträchtigen. Bei Header-Feldern, Health Checks oder Antwortnutzdaten sind die Regeln weniger streng: Nur in HTTP-Header-Feldern verbotene Zeichen werden durch ihre hexadezimale Kodierung mit vorangestelltem ‘%’ ersetzt. Normalerweise ist dies unproblematisch. Es kann aber die Ausgabe verändern, wenn ein Zeichen unverändert erwartet wird, etwa beim Erstellen einer Fehlerseite oder vollständiger Antwortnutzdaten, in denen Zeilenumbrüche als “%0A” erscheinen könnten.
Hinweis: Bei den Konfigurationsdirektiven “log-format”, “log-format-sd” und “unique-id-format” gelten Leerzeichen als Trennzeichen und werden zusammengefasst.
Hinweis: Beim syslog-Nachrichtenformat RFC5424 sollten die Zeichen ‘"’, ‘\’ und ‘]’ innerhalb von PARAM-VALUE durch ein vorangestelltes ‘\’ maskiert werden (Einzelheiten unter https://tools.ietf.org/html/rfc5424#section-6.3.3 ). In solchen Fällen sollte das Flag “E” in Betracht gezogen werden.
Folgende Element-Flags werden unterstützt und lassen sich über die Argumente des Elements aktivieren oder deaktivieren:
- Q: Eine Zeichenkette in Anführungszeichen setzen.
- X: Hexadezimale Darstellung (IPs, Ports, %Ts, %rt, %pid).
- E: Die Zeichen ‘"’, ‘\’ und ‘]’ in einer Zeichenkette durch ein vorangestelltes ‘\’ maskieren (vorgesehen für Protokollformate mit strukturierten Daten nach RFC5424).
- bin: Versuchen, Binärdaten zu erhalten. Dies kann bei Sample-Ausdrücken mit binärer Ausgabe nützlich sein, um die Originaldaten zu bewahren. Dabei können jedoch nicht druckbare Zeichen einschließlich NULL-Bytes entstehen, die die meisten syslog-Endpunkte nicht erwarten. Das Flag ist daher hauptsächlich für set-var-fmt, Ringpuffer und binärfähige Protokollendpunkte vorgesehen. Es kann nur global mit %o gesetzt werden; als Option eines einzelnen Elements wird es ignoriert.
- json: Den Wert automatisch im JSON-Format kodieren. Bei globaler Aktivierung werden nur benannte Formatelemente berücksichtigt. Unvollständige Zahlenwerte, etwa ‘%B’ bei logasap, die ohne Kodierung normalerweise ein vorangestelltes ‘+’ erhalten, werden unverändert kodiert. Die Option ‘+E’ wird außerdem ignoriert. Wie in Abschnitt 8.6 beschrieben, werden Zeichen außerhalb des Bereichs 32..126 Byte für Byte mit JSON-Escape-Sequenzen maskiert, sodass die Ausgabe unabhängig von der Eingabe aus druckbarem ASCII besteht. Dies gilt auch für gültige UTF-8-Sequenzen: Nach dem Dekodieren erscheint Nicht-ASCII-Text als seine einzelnen Bytes. Beispielsweise wird U+00E9, kodiert als 0xC3 0xA9, als “\u00C3\u00A9” protokolliert. Mit “utf8” unten lässt sich solcher Text erhalten.
- utf8: Zusammen mit “json” werden gültige UTF-8-Sequenzen aus mehreren Bytes unmaskiert ausgegeben. C1-Steuerzeichen (U+0080 bis U+009F) werden weiterhin maskiert und durch ihren Codepunkt dargestellt. Ungültige Sequenzen werden Byte für Byte maskiert, damit die Ausgabe immer gültiges UTF-8 bleibt. Da gültiges UTF-8 unverändert ausgegeben wird, kann ein Client mit bestimmten Sonderzeichen die Darstellung einer Protokollzeile im Terminal oder in einem Protokollbetrachter verändern, etwa mit Richtungswechseln, Zeichen ohne Breite oder Zeilen- und Absatztrennern. Deshalb sollte dieses Flag nur für Inhalte aus vertrauenswürdigen Quellen verwendet werden oder wenn die Protokolle nicht in einem Terminal angezeigt werden sollen. Ohne “json” hat es keine Wirkung.
- cbor: Den Wert automatisch im CBOR-Format kodieren. Bei globaler Aktivierung werden nur benannte Formatelemente berücksichtigt. Standardmäßig werden cbor-kodierte Daten in HEX-Form dargestellt, damit sie auf stdout druckbar bleiben und mit gewöhnlichen syslog-Endpunkten verwendet werden können. Wie bei json werden unvollständige Zahlenwerte unverändert kodiert und ‘+E’ ignoriert. Zusammen mit ‘+bin’ werden direkt rohe binäre CBOR-Nutzdaten erzeugt. Dabei entstehen nicht druckbare Zeichen; dies ist daher hauptsächlich für set-var-fmt, Ringpuffer und binärfähige Protokollendpunkte vorgesehen.
Beispiel:
Die derzeit definierten Aliase stehen in der folgenden Tabelle:
R = Einschränkungen: H = nur mode http; S = nur SSL; L = nur Protokollierung
8.3. Erweiterte Protokollierungsoptionen
Einige erweiterte Protokollierungsoptionen werden häufig gesucht, sind aber beim bloßen Durchsehen der Optionen schwer zu finden. Dieser Abschnitt bietet einen Einstieg in einige Optionen für eine bessere Protokollierung. Einzelheiten zur Verwendung stehen in der Schlüsselwortreferenz.
8.3.1. Protokollierung externer Tests deaktivieren
Überwachungswerkzeuge führen häufig Health Checks an HAProxy aus. Dies kann ein Load-Balancer auf Schicht 3 wie LVS oder ein kommerzieller Load-Balancer sein, aber auch ein umfassenderes Überwachungssystem wie Nagios. Bei sehr häufigen Tests stellt sich oft die Frage, wie sich deren Protokollierung deaktivieren lässt. Dafür gibt es drei Möglichkeiten:
-
Kommen die Verbindungen aus beliebigen Quellen und sind sie reine TCP-Prüfanfragen, soll oft einfach die Protokollierung von Verbindungen ohne Datenaustausch deaktiviert werden. Dazu dient “option dontlognull” im Frontend. Dies unterdrückt auch die Protokollierung von Portscans, was erwünscht sein kann oder auch nicht.
-
Die Aktion “http-request set-log-level silent” kann mit unterschiedlichen Bedingungen verwendet werden, etwa Quellnetzen, Pfaden oder User-Agents.
-
Wird eine bekannte URI für die Tests verwendet, diese mit “monitor-uri” für die Überwachung reservieren. Jeder Host, der diese Anfrage sendet, erhält dann nur das Ergebnis eines Health Checks; die Anfrage wird nicht protokolliert.
8.3.2. Vor dem Ende des Streams protokollieren
Bei einer Protokollierung erst am Verbindungsende bleibt der Ablauf während sehr langer Streams, etwa entfernter Terminalsitzungen oder großer Downloads, unsichtbar. “option logasap” im Frontend umgeht dieses Problem: HAProxy protokolliert dann möglichst früh, unmittelbar vor Beginn der Datenübertragung. Bei TCP wird weiterhin der Verbindungsstatus zum Server erfasst; bei HTTP erfolgt die Ausgabe direkt nach Verarbeitung der Server-Header. Die angegebene Bytezahl ist dann die Anzahl der an den Client gesendeten Header-Bytes. Zur Unterscheidung von gewöhnlichen Protokollen erhalten Gesamtzeit und Bytezahl ein vorangestelltes ‘+’, das auf sicher größere tatsächliche Werte hinweist.
8.3.3. Protokollstufe bei Fehlern erhöhen
Manchmal ist es praktischer, Protokolle des normalen Datenverkehrs von Fehlerprotokollen zu trennen, etwa um Fehler in Protokolldateien leichter zu überwachen. Mit “log-separate-errors” steigt die syslog-Stufe für Verbindungen mit Fehlern, Zeitüberschreitungen, Wiederholungsversuchen, Umverteilungen oder HTTP-Statuscodes 5xx von “info” auf “err”. Dadurch kann ein syslog-Daemon die Meldungen in einer eigenen Datei ablegen. Die Fehler sollten unbedingt auch in der Datei für den normalen Datenverkehr verbleiben, damit die Reihenfolge der Meldungen erhalten bleibt. Vorsicht ist auch geboten, wenn der syslog-Daemon bereits alle Meldungen oberhalb von “notice” in einer “admin”-Datei speichert, da “err” höher als “notice” liegt.
8.3.4. Protokollierung erfolgreicher Verbindungen deaktivieren
Es mag zunächst ungewöhnlich klingen, doch manche großen Websites müssen mehrere Tausend Meldungen pro Sekunde verarbeiten. Es fällt ihnen schwer, diese lange vollständig aufzubewahren oder Fehler darin zu erkennen. Ist im Frontend “dontlog-normal” gesetzt, werden normale Verbindungen nicht protokolliert. Als normal gilt dabei eine Verbindung ohne Fehler, Zeitüberschreitung, Wiederholungsversuch oder Umverteilung. Bei HTTP wird zusätzlich der Statuscode geprüft; Antworten mit Status 5xx gelten ebenfalls nicht als normal und werden protokolliert. Von dieser Einstellung wird jedoch ausdrücklich abgeraten, weil dadurch die meisten nützlichen Informationen aus den Protokollen verschwinden. Nur verwenden, wenn keine Alternative besteht.
8.3.5. Protokollprofile
Direktiven wie “log-format”, “log-format-sd”, “error-log-format” oder “log-tag” konfigurieren die Protokollformatierung global oder auf Proxy-Ebene. Es kann jedoch sinnvoll sein, diese Einstellungen möglichst nahe am Protokollziel festzulegen, also je “log”-Direktive.
Dazu dient der Abschnitt “log-profile”, der an beliebiger Stelle der Konfiguration definiert werden kann. Seine Schlüsselwörter beschreiben, wie die für eine bestimmte log-Direktive ausgegebenen Meldungen aufgebaut werden sollen.
Eine “log”-Direktive kann ein bestimmtes log-profile anhand seines Namens auswählen. Mehrere “log”-Direktiven können dasselbe Profil verwenden.
log-profile <name> Erstellt ein neues Protokollprofil mit der Kennung <name>.
log-tag <string> Überschreibt das syslog-Tag, das mit “log-tag” global oder je Proxy gesetzt wurde.
on <step> [drop] [format <fmt>] [sd <sd_fmt>] Überschreibt die Formatzeichenkette, mit der die Protokollzeile normalerweise beim Schritt <step> erzeugt wird. <fmt> überschreibt je nach <step> die Zeichenkette “log-format” oder “error-log-format”, während <sd_fmt> die Zeichenkette “log-format-sd” überschreibt. Beides kann kombiniert werden.
Mit dem besonderen Schlüsselwort “drop” wird für den angegebenen <step> keine Meldung ausgegeben. Es hat Vorrang vor zuvor definierten Angaben für “format” und “sd”.
Mögliche Werte für <step> sind:
- “accept”: log-format überschreiben, wenn die Meldung unmittelbar nach Annahme der Frontend-Verbindung entsteht.
- “request”: log-format überschreiben, wenn die Meldung nach Empfang der Clientanfrage entsteht.
- “connect”: log-format überschreiben, wenn die Meldung nach Aufbau der Backend-Verbindung entsteht.
- “response”: log-format überschreiben, wenn die Meldung während der Verarbeitung der Serverantwort entsteht.
- “close”: log-format überschreiben, wenn die Meldung im letzten Transaktionsschritt (txn) entsteht.
- “error”: error-log-format überschreiben, wenn die Meldung aufgrund eines Transaktionsfehlers entsteht.
- “any”: log-format und error-log-format für alle Protokollierungsschritte überschreiben, sofern keine genauere Festlegung für einen einzelnen Schritt vorliegt.
Weitere relevante Werte für <step> stehen bei der Aktion “do-log”.
Diese Einstellung ist nur für “log”-Direktiven in Kontexten relevant, in denen “log-format” sinnvoll ist, etwa bei http- und tcp-Proxys. Andernfalls wird sie ignoriert.
Beispiel:
8.4. Zeitmessungen
Zeitmessungen helfen sehr bei der Untersuchung von Netzwerkproblemen. Alle Werte werden in Millisekunden (ms) angegeben und sollten zusammen mit den Flags zur Stream-Beendigung ausgewertet werden. Im TCP-Modus mit “option tcplog” im Frontend werden 3 Messpunkte als “Tw/Tc/Tt” ausgegeben, im HTTP-Modus 5 als “TR/Tw/Tc/Tr/Ta”. Hinzu kommen drei weitere Messwerte: “Th”, “Ti” und “Tq”.
Zeitmessungen im HTTP-Modus:
Zeitmessungen im TCP-Modus:
-
Th: Gesamtdauer für die Annahme der TCP-Verbindung und die Handshakes der Protokolle niedrigerer Schichten, derzeit proxy-protocol und SSL. Dies kann während der gesamten Verbindungsdauer nur einmal geschehen. Ein hoher Wert kann bedeuten, dass der Client nur vorab eine Verbindung aufgebaut, aber noch nichts gesendet hat, dass Netzwerkprobleme wie MTU-Probleme den rechtzeitigen Abschluss des Handshakes verhindern oder dass die Berechnung des SSL-Handshakes sehr aufwendig war. Diese Zeit wird nur vor der ersten Anfrage angegeben. Sie kann daher über alle Anfragen gemittelt werden, um den anteiligen Aufwand zu ermitteln. Bei der zweiten und allen folgenden Anfragen wird hier stets null ausgegeben.
Dieser Messwert heißt als log-format-Alias %Th und als Sample-Abruf fc.timer.handshake.
-
Ti: Leerlaufzeit vor der HTTP-Anfrage, nur im HTTP-Modus. Gemessen wird zwischen dem Ende der Handshakes und dem ersten Byte der HTTP-Anfrage. Bei einer zweiten Anfrage im Keep-Alive-Modus beginnt die Messung nach dem Ende der Übertragung der vorherigen Antwort. Bei einem Multiplex-Protokoll wie HTTP/2 beginnt sie unmittelbar nach der vorherigen Anfrage. Manche Browser bauen Verbindungen vorab auf, um die Latenz einer späteren Anfrage zu verringern, und halten sie bis zur Verwendung offen. Diese Verzögerung erscheint als Leerlaufzeit. Ein Wert von -1 bedeutet, dass auf der Verbindung nichts empfangen wurde.
Dieser Messwert heißt als log-format-Alias %Ti und als Sample-Abruf req.timer.idle.
-
TR: Gesamtdauer für den Empfang der Clientanfrage, nur im HTTP-Modus. Dies ist die Zeit vom Empfang der ersten Bytes bis zur Leerzeile, die das Ende der HTTP-Header markiert. “-1” bedeutet, dass das Header-Ende nie empfangen wurde. Dies geschieht bei vorzeitigem Schließen durch den Client oder einer Zeitüberschreitung. Die Dauer ist gewöhnlich sehr kurz, da die meisten Anfragen in ein einziges Paket passen. Ein hoher Wert kann auf eine bei einem Test von Hand eingegebene Anfrage hinweisen.
Dieser Messwert heißt als log-format-Alias %TR und als Sample-Abruf req.timer.hdr.
-
Tq: Gesamtdauer für den Empfang der Clientanfrage ab Verbindungsannahme oder ab dem Senden des letzten Bytes der vorherigen Antwort, nur im HTTP-Modus. Sie entspricht genau Th + Ti + TR, außer wenn einer dieser Werte -1 ist; dann ist auch Tq gleich -1. Vor HTTP Keep-Alive und dem vorzeitigen Verbindungsaufbau durch Browser war dieser Wert sehr nützlich. Heute wird empfohlen, stattdessen TR zu verwenden, da die Leerlaufzeit die Berichte stark mit Schwankungen belastet.
Dieser Messwert heißt als log-format-Alias %Tq und als Sample-Abruf req.timer.tq.
-
Tw: Gesamte Wartezeit in den Warteschlangen auf einen freien Verbindungsplatz. Sie berücksichtigt die Backend- und Serverwarteschlangen und hängt von deren Größe sowie davon ab, wie lange der Server für vorherige Anfragen benötigt. “-1” bedeutet, dass die Anfrage vor Erreichen der Warteschlange beendet wurde, was meist bei ungültigen oder abgewiesenen Anfragen geschieht.
Dieser Messwert heißt als log-format-Alias %Tw und als Sample-Abruf req.timer.queue.
-
Tc: Gesamtdauer für den Aufbau der TCP-Verbindung zum Server. Dies ist die Zeit zwischen dem Senden der Verbindungsanfrage durch den Proxy und ihrer Bestätigung durch den Server, also zwischen TCP-SYN-Paket und zugehörigem SYN/ACK-Antwortpaket. “-1” bedeutet, dass keine Verbindung zustande kam.
Dieser Messwert heißt als log-format-Alias %Tc und als Sample-Abruf bc.timer.connect.
-
Tr: Antwortzeit des Servers, nur im HTTP-Modus. Dies ist die Zeit zwischen dem Aufbau der TCP-Verbindung zum Server und dem Senden seiner vollständigen Antwort-Header. Sie gibt ausschließlich die Bearbeitungszeit der Anfrage ohne den Netzwerkaufwand für die Datenübertragung an. Muss der Client Daten an den Server senden, etwa bei einer POST-Anfrage, läuft die Messung jedoch bereits, was die scheinbare Antwortzeit verfälschen kann. Bei POST-Anfragen von Clients hinter einem nicht vertrauenswürdigen Netzwerk sollte diesem Feld daher gewöhnlich nur eingeschränkt vertraut werden. “-1” bedeutet, dass der letzte Antwort-Header, die Leerzeile, nie empfangen wurde. Meist ist dann die Serverzeitgrenze vor Verarbeitung der Anfrage abgelaufen oder der Server hat eine ungültige Antwort geliefert.
Dieser Messwert heißt als log-format-Alias %Tr und als Sample-Abruf res.timer.hdr.
-
Td: Gesamtdauer der Übertragung der Antwortnutzdaten bis zum letzten an den Client gesendeten Byte. Bei HTTP beginnt sie nach dem letzten Antwort-Header, also nach Tr.
Es ist nicht garantiert, dass die gesendeten Daten beim Client ankommen; sie können im Kernel oder im Netzwerk festhängen.
Dieser Messwert heißt als log-format-Alias %Td und als Sample-Abruf res.timer.data.
-
Ta: Gesamte aktive Zeit der HTTP-Anfrage vom Empfang des ersten Bytes ihres Headers durch den Proxy bis zum Senden des letzten Bytes des Antwortkörpers. Eine Ausnahme besteht bei der Option “logasap”: Dann entspricht sie nur (TR+Tw+Tc+Tr) und erhält ein vorangestelltes ‘+’. Daraus lässt sich die Datenübertragungszeit “Td” durch Abziehen der übrigen gültigen Messwerte berechnen:
Messwerte mit dem Wert "-1" müssen aus dieser Gleichung ausgeschlossen werden.
"Ta" kann niemals negativ sein.
Dieser Messwert heißt als log-format-Alias %Ta und als Sample-Abruf txn.timer.total.
- Tt: Gesamtdauer des Streams von der Annahme durch den Proxy bis zum Schließen beider Seiten. Eine Ausnahme besteht bei der Option “logasap”: Dann entspricht sie nur (Th+Ti+TR+Tw+Tc+Tr) und erhält ein vorangestelltes ‘+’. Daraus lässt sich die Datenübertragungszeit “Td” durch Abziehen der übrigen gültigen Messwerte berechnen:
Messwerte mit dem Wert "-1" müssen aus dieser Gleichung ausgeschlossen werden.
Im TCP-Modus müssen außerdem "Ti", "Tq" und "Tr" ausgeschlossen werden.
"Tt" kann niemals negativ sein; bei HTTP entspricht Tt einfach (Th+Ti+Ta).
Dieser Messwert heißt als log-format-Alias %Tt und als Sample-Abruf fc.timer.total.
-
Tu: Geschätzte Gesamtdauer aus Sicht des Clients von der Annahme durch den Proxy bis zum Schließen beider Seiten, ohne Leerlaufzeit. Damit lässt sich die vom Nutzer wahrgenommene Gesamtdauer grob messen, ohne den Einfluss der Keep-Alive-Leerlaufzeit zwischen Anfragen. Es ist nur eine Schätzung, da sie gleiche Netzwerklatenzen in beiden Richtungen voraussetzt. Eine Ausnahme besteht bei der Option “logasap”: Dann entspricht sie nur (Th+TR+Tw+Tc+Tr) und erhält ein vorangestelltes ‘+’.
Dieser Messwert heißt als log-format-Alias %Tu und als Sample-Abruf txn.timer.user.
Diese Zeitmessungen liefern wertvolle Hinweise auf Fehlerursachen. Da TCP Wiederholungsintervalle von 3, 6, 12… Sekunden vorgibt, hängen Werte nahe Vielfachen von 3s fast immer mit Paketverlusten durch Netzwerkprobleme zusammen, etwa Kabel, Aushandlung oder Überlastung. Liegt “Ta” oder “Tt” nahe einer konfigurierten Zeitgrenze, wurde ein Stream häufig wegen einer Zeitüberschreitung abgebrochen.
Die häufigsten Fälle:
-
Liegt “Th” oder “Ti” nahe bei 3000, ging wahrscheinlich ein Paket zwischen Client und Proxy verloren. In lokalen Netzen ist dies sehr selten, kann aber bei weit entfernten Clients mit großen Anfragen auftreten. Höhere Werte können auch ohne Netzwerkproblem entstehen. Während eines Angriffs oder unmittelbar nach dem Ende eines Ressourcenengpasses nimmt HAProxy manchmal Tausende Verbindungen innerhalb weniger Millisekunden an. Die dafür benötigte Zeit verzögert zwangsläufig die Verarbeitung anderer Verbindungen etwas. Werden einige Tausend Verbindungen gleichzeitig angenommen, können daher Anfragezeiten von einigen zehn Millisekunden entstehen. In einem Keep-Alive-Modus können längere Leerlaufzeiten erscheinen, da “Ti” die Wartezeit auf weitere Anfragen misst.
-
Liegt “Tc” nahe bei 3000, ging beim Verbindungsaufbau wahrscheinlich ein Paket zwischen Server und Proxy verloren. Dieser Wert sollte stets sehr niedrig sein, etwa 1 ms in lokalen Netzen und weniger als einige zehn ms in entfernten Netzen.
-
Liegt “Tr” fast immer unter 3000, mit wenigen Ausnahmen, die ungefähr dem Durchschnitt zuzüglich 3000 entsprechen, gehen wahrscheinlich Pakete zwischen Proxy und Server verloren.
-
Ist “Ta” selbst bei kleinen Bytezahlen groß, schließen häufig weder Client noch Server die Verbindung, während HAProxy im Tunnelmodus arbeitet und beide einen Keep-Alive-Modus vereinbart haben. Zur Behebung muss eine HTTP-Option verwendet werden, die Keep-Alive oder das Schließen im Frontend oder Backend beeinflusst. Bei Verbindungsregelung mit “maxconn” auf den Servern sind möglichst kleine Werte für ‘Ta’ oder ‘Tt’ wichtig: Erst wenn eine Verbindung freigegeben wird, erhält der Server eine neue.
Weitere auffällige Fälle im HTTP-Protokoll (‘xx’ steht für einen beliebigen, zu ignorierenden Wert):
8.5. Stream-Zustand bei der Trennung
TCP- und HTTP-Protokolle enthalten unmittelbar vor der Anzahl aktiver Verbindungen im Feld “termination_state” ein Kennzeichen zur Stream-Beendigung. Im TCP-Modus ist es 2 Zeichen lang, im HTTP-Modus 4. Jedes Zeichen hat eine eigene Bedeutung:
- Das erste Zeichen bezeichnet das erste Ereignis, das zur Beendigung des Streams führte:
- Das zweite Zeichen bezeichnet den Zustand des TCP- oder HTTP-Streams beim Schließen:
- Das dritte Zeichen gibt an, ob der Client das Persistenz-Cookie mitgesendet hat, nur im HTTP-Modus:
- Das letzte Zeichen beschreibt die Aktionen am vom Server zurückgegebenen Persistenz-Cookie, nur im HTTP-Modus:
Die Kombination der ersten beiden Flags zeigt ausführlich, was beim Ende des Streams oder der Sitzung geschah und warum er beziehungsweise sie beendet wurde. Sie hilft etwa, überlastete Server, Netzwerkprobleme, lokale Ressourcenengpässe und Angriffe zu erkennen.
Die häufigsten Kombinationen von Beendigungsflags stehen unten in alphabetischer Reihenfolge. Zur leichteren Orientierung folgt die Variante mit Kleinbuchstaben jeweils direkt auf die mit Großbuchstaben.
Flags Grund
-- Normale Beendigung.
CC Der Client brach ab, bevor die Verbindung zum Server aufgebaut war.
Dies kann geschehen, wenn HAProxy einen kürzlich ausgefallenen oder
ungeprüften Server zu erreichen versucht und der Client abbricht,
während HAProxy auf dessen Antwort oder auf "timeout connect" wartet.
CD Der Client brach während der Datenübertragung unerwartet ab. Mögliche
Ursachen sind ein Browserabsturz, ein zwischengeschaltetes Gerät,
das die Verbindung zwischen Client und HAProxy aktiv trennt,
Routingprobleme auf diesem Weg oder ein Keep-Alive-Stream zwischen
Server und Client, den zuerst der Client beendet.
cD Der Client hat während der gesamten Dauer von "timeout client"
weder Daten gesendet noch bestätigt. Häufig sind Netzwerkfehler
auf der Clientseite oder ein unsauberes Verlassen des Netzwerks
durch den Client die Ursache.
CH Der Client brach ab, während er auf den Beginn der Serverantwort
wartete. Möglicherweise antwortete der Server zu langsam, oder
der Client klickte zu früh auf 'Stop'.
cH "timeout client" lief beim Warten auf Clientdaten während einer
POST-Anfrage ab. Eine Ursache können zu große TCP-MSS-Werte für
PPPoE-Netze sein, die keine Pakete voller Größe übertragen können.
Dies kann auch auftreten, wenn die Clientzeitgrenze kleiner als
die Serverzeitgrenze ist und der Server zu lange zum Antworten braucht.
CQ Der Client brach ab, während sein Stream auf einen Server mit
genügend freien Verbindungsplätzen wartete. Möglicherweise waren
alle Server ausgelastet oder der zugewiesene Server antwortete zu langsam.
CR Der Client brach ab, bevor er eine vollständige HTTP-Anfrage gesendet
hatte. Wahrscheinlich wurde die Anfrage von Hand mit einem telnet-Client
eingegeben und zu früh abgebrochen. Der HTTP-Statuscode ist hier
vermutlich 400. Gelegentlich kann auch ein IDS die Verbindung zwischen
HAProxy und Client beenden. Mit "option http-ignore-probes" lassen
sich Verbindungen ohne Datenaustausch ignorieren.
cR "timeout http-request" lief ab, bevor der Client eine vollständige
HTTP-Anfrage gesendet hatte. Mögliche Ursachen sind zu große TCP-MSS-
Werte auf der Clientseite für PPPoE-Netze, die keine Pakete voller
Größe übertragen können, zu langsam von Hand eingegebene Anfragen
oder eine vergessene Leerzeile am Anfrageende. Der HTTP-Statuscode
ist hier vermutlich 408. Hinweis: Einige Browser haben seit Kurzem
eine "pre-connect"-Funktion. Sie verbinden sich vorsorglich mit kürzlich
besuchten Websites, falls der Nutzer sie erneut aufrufen möchte.
Dadurch entstehen viele Verbindungen, die bei zuerst ablaufender
Zeitgrenze mit 408 Request Timeout oder bei vorherigem Schließen
durch den Browser mit 400 Bad Request enden. Sie füllen die Protokolle
und erhöhen Fehlerzähler. Manche Versionen einiger Browser sollen
sogar den Fehlercode anzeigen. Mit "option http-ignore-probes" im
Frontend lassen sich diese unerwünschten Auswirkungen umgehen:
Verbindungen ohne Datenübertragung werden vollständig ignoriert.
Dadurch werden allerdings auch Fehler von Nutzern mit
Verbindungsproblemen verborgen.
CT Der Client brach ab, während sein Stream mit tarpit verzögert wurde.
Es ist wichtig zu prüfen, ob dies bei gültigen Anfragen geschieht,
um fehlerhafte tarpit-Regeln auszuschließen. Bei vielen solchen
Fällen kann es sinnvoll sein, "timeout tarpit" näher an den
durchschnittlichen Messwert "Tw" zu senken, damit nicht wenige
Angreifer unnötig Ressourcen binden.
LC HAProxy fing die Anfrage ab und verarbeitete sie lokal. Sie wurde
nicht an den Server gesendet. Dies tritt nur bei einer Weiterleitung
durch einen Parameter "redir" in der Serverzeile auf.
LR HAProxy fing die Anfrage ab und verarbeitete sie lokal. Sie wurde
nicht an den Server gesendet. Gewöhnlich wurde eine Weiterleitung
zurückgegeben, eine HTTP-return-Anweisung verarbeitet oder die
Anfrage von einem Applet bearbeitet, etwa stats, cache,
Prometheus-Exporter oder Lua-Applet.
LH HAProxy fing die Antwort ab und verarbeitete sie lokal. Gewöhnlich
wurde eine Weiterleitung zurückgegeben oder eine HTTP-return-Anweisung
verarbeitet.
SC Der Server oder ein Gerät zwischen ihm und HAProxy wies die
TCP-Verbindung ausdrücklich zurück; der Proxy empfing ein TCP-RST
oder eine ICMP-Nachricht. Unter bestimmten Umständen meldet auch
der Netzwerk-Stack, dass der Server nicht erreichbar ist, etwa
wegen einer fehlenden Route oder ARP-Antwort im lokalen Netz.
Im HTTP-Modus ist der Statuscode dann vermutlich 502 oder 503.
sC "timeout connect" lief ab, bevor die Verbindung zum Server
vollständig aufgebaut war. Im HTTP-Modus ist der Statuscode
dann vermutlich 503 oder 504.
SD Die Serververbindung endete während der Datenübertragung mit einem
Fehler. Gewöhnlich hat HAProxy beim Datenaustausch ein RST vom
Server oder eine ICMP-Nachricht eines zwischengeschalteten Geräts
empfangen. Ursache kann ein Serverabsturz oder ein Netzwerkproblem
an einem zwischengeschalteten Gerät sein.
sD Der Server hat während der Datenphase für die gesamte Dauer von
"timeout server" weder Daten gesendet noch bestätigt. Häufige
Ursachen sind zu kurze Zeitgrenzen auf vorgeschalteten L4-Geräten
wie Firewalls oder Load-Balancern sowie Keep-Alive-Sitzungen zwischen
Client und Server, deren Zeitgrenze zuerst in HAProxy abläuft.
SH Der Server brach vor dem Senden seiner vollständigen HTTP-Antwort-
Header ab oder stürzte bei der Anfrageverarbeitung ab. Ein Abbruch
zu diesem Zeitpunkt ist sehr selten. Daher sollten seine Protokolle
darauf geprüft werden, ob und warum er abgestürzt ist. Die
protokollierte Anfrage kann auf eine kleine Gruppe fehlerhafter
Anfragen hinweisen, die Programmfehler in der Anwendung auslösen.
Gelegentlich kann auch ein IDS die Verbindung zwischen HAProxy
und dem Server beenden.
sH "timeout server" lief ab, bevor der Server seine Antwort-Header
zurückgeben konnte. Dies ist die häufigste Auffälligkeit und deutet
auf zu lange Transaktionen hin, vermutlich wegen überlasteter Server
oder Datenbanken. Kurzfristig hilft ein höherer Wert für "timeout server".
Die langen Antwortzeiten beeinträchtigen aber die Nutzererfahrung.
Die einzige dauerhafte Lösung besteht darin, die Anwendung zu korrigieren.
sQ Der Stream wartete zu lange in der Warteschlange und lief ab.
Tritt dies zu oft auf, die Einstellungen "timeout queue" und
"timeout connect" prüfen. Viele solche Fälle in kurzen Zeiträumen
können auf allgemeine Serverprobleme durch I/O- oder Datenbankengpässe
oder auf Überlastung durch externe Angriffe hindeuten.
PC Der Proxy verweigerte den Verbindungsaufbau zum Server, weil beim
Versuch die Socket-Grenze des Prozesses erreicht wurde. Der globale
Parameter "maxconn" kann erhöht werden, um dies zu verhindern.
Dieser Zustand ist sehr selten und kann auftreten, wenn der globale
Parameter "ulimit-n" von Hand erzwungen wird.
PD Nach dem Senden der Server-Header blockierte der Proxy eine fehlerhaft
formatierte Nachricht mit Chunked-Kodierung in einer Anfrage oder
Antwort. Meist handelt es sich um eine ungültige Nachricht vom Server
an den Client. HAProxy unterstützt Chunk-Größen bis 2GB - 1
(2147483647 Bytes). Größere Werte gelten als Fehler.
PH Der Proxy blockierte die Serverantwort, weil sie ungültig,
unvollständig, gefährlich hinsichtlich der Cache-Steuerung war oder
einem Sicherheitsfilter entsprach. Dabei erhält der Client einen
HTTP-Fehler 502. Eine mögliche Ursache ist ein HTTP-Headername mit
unzulässigen Zeichen. Selten kann der Proxy auch vor der Serverantwort
eine syntaktisch ungültige Clientanfrage mit Chunked-Kodierung
blockieren. Dann erhält der Client einen HTTP-Fehler 400, der auch
protokolliert wird. Schließlich kann ein Fehler beim Umschreiben
eines Antwort-Headers die Ursache sein. Dann wird ein HTTP-Fehler
500 gesendet; siehe "tune.maxrewrite" und "http-response strict-mode".
PR Der Proxy blockierte die HTTP-Anfrage des Clients: Bei ungültiger
HTTP-Syntax antwortete er mit einem HTTP-Fehler 400, bei einem
passenden deny-Filter mit einem HTTP-Fehler 403. Auch ein Fehler
beim Umschreiben eines Anfrage-Headers ist möglich. Dann wird
ein HTTP-Fehler 500 gesendet; siehe "tune.maxrewrite" und
"http-request strict-mode".
PT Der Proxy blockierte die Clientanfrage und verzögerte die Verbindung
mit tarpit, bevor er einen Serverfehler 500 zurückgab. An den Server
wurde nichts gesendet. Die Verbindung blieb so lange offen,
wie der Messwert "Tw" angibt.
RC Eine lokale Ressource war erschöpft, etwa Speicher, Sockets oder
Quellports, sodass die Serververbindung nicht aufgebaut werden konnte.
Die Fehlerprotokolle nennen genau die fehlende Ressource. Dies ist
sehr selten und lässt sich nur durch geeignete Systemanpassungen beheben.
Die Kombination der letzten beiden Flags zeigt ausführlich, wie Client, Server und HAProxy die Persistenz behandelt haben. Das ist bei Verbindungsabbrüchen sehr wichtig, wenn Nutzer über wiederholte Authentifizierung klagen. Häufig treten folgende Flags auf:
8.6. Nicht druckbare Zeichen
Damit Protokollauswertungswerkzeuge und Terminals beim Lesen der Protokolle keine Probleme bekommen, werden nicht druckbare Zeichen nicht unverändert ausgegeben. Stattdessen erscheint ihr zweistelliger hexadezimaler ASCII-Code mit vorangestelltem ‘#’. Nur Zeichen zwischen 32 und 126 einschließlich können unmaskiert protokolliert werden. Das Maskierungszeichen ‘#’ selbst wird zur Vermeidung von Mehrdeutigkeiten ebenfalls kodiert, als “#23”. Dasselbe gilt für ‘"’, das zu “#22” wird, sowie beim Protokollieren von Headern für ‘{’, ‘|’ und ‘}’.
Dies gilt nicht für die cbor-Kodierung, die bereits sichere Hexadezimalziffern oder korrekt abgegrenzte Binärblöcke verwendet. Diese werden nicht an ein Terminal gesendet, sondern von einem CBOR-Parser verarbeitet.
Die json-Kodierung verwendet stattdessen JSON-Escape-Sequenzen. Mit der Option +utf8 werden außerdem gültige UTF-8-Sequenzen aus mehreren Bytes unverändert ausgegeben (siehe das Flag “utf8” in Abschnitt 8.2.6 ).
Das Leerzeichen (’ ‘) wird in Headern nicht kodiert. Dies kann Werkzeuge beeinträchtigen, die Felder anhand der Anzahl von Leerzeichen bestimmen. Ein typischer Header mit Leerzeichen ist “User-Agent”.
Einige syslog-Daemons wie syslog-ng maskieren das Anführungszeichen (’"’) mit einem Backslash (’\’). Dies kann gefahrlos rückgängig gemacht werden, da Anführungszeichen sonst nirgendwo in den Protokollen vorkommen dürfen.
8.7. HTTP-Cookies erfassen
Das Erfassen von Cookies erleichtert es, eine vollständige Nutzersitzung zu verfolgen. Dazu dient “capture cookie” im Frontend; Einzelheiten stehen in Abschnitt 4.2 . Es kann nur ein Cookie erfasst werden. Dasselbe Cookie wird gleichzeitig in der Anfrage (Header “Cookie:”) und in der Antwort (Header “Set-Cookie:”) geprüft. Die jeweiligen Werte erscheinen im HTTP-Protokoll in “captured_request_cookie” und “captured_response_cookie” (siehe Abschnitt 8.2.3 zum HTTP-Protokollformat). Fehlt eines der Cookies, steht statt seines Werts ein Bindestrich (’-’). Dadurch lässt sich etwa der Wechsel eines Nutzers in eine neue Sitzung leicht erkennen, da ihm der Server ein neues Cookie zuweist. Auch ein unerwartet falsch gesetztes Cookie, das Sitzungen zwischen Clients verwechselt, lässt sich so erkennen.
Beispiele:
Für weitergehende Erfassungen können “http-request”- und “http-response”-Regeln Cookies Variablen des Geltungsbereichs “txn” zuweisen. Die Werte lassen sich mit den Sample-Abruffunktionen “req.cook” und “res.cook” aus Anfrage oder Antwort auslesen (siehe Abschnitt 7.3.6 ) und mit “set-var” oder “set-var-fmt” einer Variablen zuweisen (siehe Abschnitt 4.3 ). Ein benutzerdefiniertes log-format kann diese Variablen dann an beliebiger Stelle ausgeben (siehe Abschnitt 8.2.6 ).
8.8. HTTP-Header erfassen (älteres Verfahren)
Das Erfassen von Headern hilft, eindeutige Anfragekennungen eines vorgeschalteten Proxys, virtuelle Hostnamen, User-Agents, content-length bei POST-Anfragen, Referrer und Ähnliches zu verfolgen. In Antworten lassen sich etwa Angaben zur Antwortlänge, zu den Vorgaben des Servers für den Cache oder zum Zielort eines Objekts bei einer Weiterleitung ermitteln.
Es gibt zwei Verfahren zur Header-Erfassung. Beim modernen Verfahren werden Variablen aus den gewünschten Headern oder aus zusammengesetzten Samples von “req.hdr_names”, “req.hdrs”, “res.hdr_names” und “res.hdrs” gesetzt; alle Möglichkeiten stehen in Abschnitt 7.3.6 . Mit den Aktionen “set-var” und “set-var-fmt” der Regelsätze “http-request” und “http-response” lassen sie sich Variablen des Geltungsbereichs “txn” zuweisen (siehe Abschnitt 4.3 ). Diese können dann in benutzerdefinierten Protokollformaten referenziert werden (siehe Abschnitt 8.2.6 ). Dies ist das empfohlene Verfahren zur Erfassung von HTTP-Headern.
Daneben gibt es das ältere Verfahren aus der Zeit vor http-request-Regeln und Variablen. Es erfordert keine Anpassung des Protokollformats und wird seit Langem sowohl zur Protokollierung als auch als Behelf verwendet, um Anfrageinformationen über die gesamte HTTP-Transaktion hinweg weiterzugeben. Es verwendet die älteren “capture”-Regelsätze und wird in diesem Abschnitt beschrieben.
Beim älteren Verfahren werden Header mit “capture request header” und “capture response header” im Frontend erfasst. Einzelheiten stehen in den Definitionen in Abschnitt 4.2 .
Anfrage- und Antwort-Header können gleichzeitig erfasst werden. Fehlende Header werden als leere Zeichenketten protokolliert. Kommt ein Header mehrfach vor, wird nur das letzte Vorkommen erfasst. Anfrage-Header werden in der Reihenfolge ihrer Deklaration innerhalb geschweifter Klammern ‘{’ und ‘}’ zusammengefasst und durch ‘|’ ohne Leerzeichen getrennt. Antwort-Header haben dieselbe Darstellung und folgen nach einem Leerzeichen auf den Block der Anfrage-Header. Beide Blöcke stehen im Protokoll unmittelbar vor der HTTP-Anfrage.
Als Sonderfall kann die Erfassung eines HTTP-Headers in einem TCP-Frontend definiert werden. Damit lassen sich Header protokollieren, die in einem HTTP-Backend ausgewertet werden, wenn die Anfrage anschließend an dieses Backend übergeben wird.
Beispiel:
8.9. Protokollbeispiele
Die folgenden Protokollbeispiele mit Erläuterungen stammen aus der Praxis; einige wurden von Hand erstellt. Zur besseren Lesbarkeit wurde der syslog-Teil entfernt. Sie sollen ausschließlich erklären, wie die Meldungen zu lesen sind.
>>> haproxy[674]: 127.0.0.1:33318 [15/Oct/2003:08:31:57.130] px-http \
px-http/srv1 6559/0/7/147/6723 200 243 - - ---- 5/3/3/1/0 0/0 \
"HEAD / HTTP/1.0"
=> Eine lange Anfrage (6.5s) wurde von Hand über 'telnet' eingegeben.
Der Server antwortete in 147 ms; die Sitzung endete normal ('----').
>>> haproxy[674]: 127.0.0.1:33319 [15/Oct/2003:08:31:57.149] px-http \
px-http/srv1 6559/1230/7/147/6870 200 243 - - ---- 324/239/239/99/0 \
0/9 "HEAD / HTTP/1.0"
=> Wie zuvor, aber die Anfrage stand hinter 9 anderen Anfragen in
der globalen Warteschlange und wartete dort 1230 ms.
=> Anfrage für eine lange Datenübertragung. Da "logasap" gesetzt war,
wurde die Meldung unmittelbar vor der Datenübertragung ausgegeben.
Der Server antwortete in 14 ms, 243 Header-Bytes wurden an den Client
gesendet, und von der Annahme bis zum ersten Datenbyte vergingen 30 ms.
>>> haproxy[674]: 127.0.0.1:33320 [15/Oct/2003:08:32:17.925] px-http \
px-http/srv1 9/0/7/14/30 502 243 - - PH-- 3/2/2/0/0 0/0 \
"GET /cgi-bin/bug.cgi? HTTP/1.0"
=> Der Proxy blockierte eine Serverantwort: entweder aufgrund einer
"http-response deny"-Regel, wegen eines fehlerhaften, nicht HTTP-konformen
Formats oder weil sensible Informationen hätten zwischengespeichert
werden können. Die Antwort wird dann durch "502 bad gateway" ersetzt.
Die Flags ("PH--") zeigen, dass HAProxy die 502 zurückgab, nicht der Server.
>>> haproxy[18113]: 127.0.0.1:34548 [15/Oct/2003:15:18:55.798] px-http \
px-http/`<NOSRV>` -1/-1/-1/-1/8490 -1 0 - - CR-- 2/2/2/0/0 0/0 ""
=> Der Client vervollständigte seine Anfrage nie und brach nach 8.5s
selbst ab ("C---"), während der Proxy auf die Anfrage-Header wartete
("-R--"). An keinen Server wurde etwas gesendet.
>>> haproxy[18113]: 127.0.0.1:34549 [15/Oct/2003:15:19:06.103] px-http \
px-http/`<NOSRV>` -1/-1/-1/-1/50001 408 0 - - cR-- 2/2/2/0/0 0/0 ""
=> Der Client vervollständigte seine Anfrage nie. Nach 50s wurde sie
durch die Zeitüberschreitung abgebrochen ("c---"), während der Proxy
auf die Anfrage-Header wartete ("-R--"). An keinen Server wurde etwas
gesendet; der Proxy konnte dem Client jedoch den Statuscode 408 senden.
>>> haproxy[18989]: 127.0.0.1:34550 [15/Oct/2003:15:24:28.312] px-tcp \
px-tcp/srv1 0/0/5007 0 cD 0/0/0/0/0 0/0
=> Diese Meldung wurde mit "option tcplog" erzeugt. Die Clientzeitgrenze
lief nach 5 Sekunden ab ("c----").
>>> haproxy[18989]: 10.0.0.1:34552 [15/Oct/2003:15:26:31.462] px-http \
px-http/srv1 3183/-1/-1/-1/11215 503 0 - - SC-- 205/202/202/115/3 \
0/0 "HEAD / HTTP/1.0"
=> Die Anfrage benötigte 3s bis zur Vollständigkeit, vermutlich wegen
eines Netzwerkproblems. Die Serververbindung schlug nach 4 Versuchen
von je 2 Sekunden fehl ('SC--'); konfiguriert war 'retries 3'. Es gab
keine Umverteilung, sonst wäre "/+3" zu sehen. Der Client erhielt
Statuscode 503. Auf diesem Server bestanden 115 Verbindungen, auf
diesem Proxy 202 und im gesamten Prozess 205. Möglicherweise wies
der Server die Verbindung wegen zu vieler bestehender Verbindungen ab.