Logs und Fehler ohne Geheimnisse

ben hat versucht, anas Buch zu löschen, und eine 404 bekommen. Sechs falsche Passwörter für ana endeten in einer 429. Wer würde das je erfahren? Dein Server hat beides abgelehnt und von keinem von beiden etwas festgehalten.

Ein Server, der ablehnt, muss seine Ablehnungen aufschreiben. Und was ein Server aufschreibt, wird von mehr Leuten gelesen und länger aufbewahrt als fast alles andere, was er erzeugt: von Betreibern, vom Support, von Backup-Systemen, von jedem, dem eine Datei gegeben wird, um einem Problem nachzugehen. Ein Log ist die einfachste Stelle, an der ein Geheimnis geleakt wird, das jeder andere Teil des Servers schützt.

Was nie in ein Log gehört

• Der Wert von Authorization. Bei einer Anmeldung ist er ein Passwort in Base64. Bei einer Anfrage nach Büchern ist er ein Token, das 15 Minuten lang funktioniert.

• Ein Cookie-Wert. Eine Session-ID ist der Berechtigungsnachweis, sobald die Anmeldung vorbei ist.

• Ein Passwort oder ein Token in irgendeiner anderen Form.

• Der Query-String. Tokens, E-Mail-Adressen und Suchwörter landen dort.

Python hat für echte Dienste ein Modul logging. Dieser Kurs verwendet es nicht. Hier ist das Log eine Liste von Textzeilen in state["log"], damit ein Test sie lesen kann.

Fünf Felder

Eine Anfrage, eine Zeile, fünf Felder mit je einem Leerzeichen dazwischen: die Zeit in ganzen Sekunden, die Methode, der Pfad, der Status und der Benutzer. Mit der Uhr fest auf 1000000 sehen ben, der ein Token holt, ben, der versucht, anas Buch zu löschen, und jemand, dessen Anmeldung scheitert, so aus:

1000000 POST /login 200 ben
1000000 POST /tokens 200 ben
1000000 DELETE /books/1 404 ben
1000000 POST /login 401 -

log_line(now, request, status, user) gibt eine solche Zeile zurück. int(now) lässt den Bruchteil der Zeit weg. request["target"].partition("?")[0] lässt die Query weg: partition teilt Text am ersten ? in drei Teile, den Text davor, das ? selbst und den Text danach, und [0] ist der erste Teil. Wenn es kein ? gibt, ist der erste Teil der ganze Text.

Warum nicht urlsplit, das du in HTTP with Python verwendet hast? Es parst das ganze Ziel, und manche Ziele lehnt es mit einem Fehler ab. urlsplit("http://[") löst ValueError aus. Eine Log-Zeile wird für jede Anfrage geschrieben, auch für die seltsamen, also darf der Code, der sie schreibt, nicht scheitern können. partition funktioniert mit jedem Text.

Der Pfad, wie er angekommen ist

Schreib den Pfad genau so ins Log, wie er angekommen ist, noch prozentkodiert. Dekodiere ihn nicht.

Ein Pfad kann %0A enthalten. Dekodiert ist das ein Zeilenumbruch, und ein Zeilenumbruch in einer Log-Zeile beginnt eine neue Zeile. Ein Fremder könnte dann eine zweite Zeile nach eigener Wahl in dein Log schreiben, eine, die wie eine Anfrage aussieht, die nie stattgefunden hat. Kodiert ist %0A drei harmlose Zeichen.

Das ist ein erster Blick auf ein Muster, um das es im ganzen Kapitel 7 geht: Text aus einer Anfrage, der irgendwo landet, wo er als Struktur gelesen wird.

Die Behebung hat eine Grenze. Andere Steuerzeichen können weiterhin eine Methode oder einen Pfad erreichen, und ein echtes Log escapt auch diese, bevor es eine Zeile schreibt.

Wessen Name

Das fünfte Feld ist request["user"]. Das Projekt setzt es an drei Stellen: wenn ein Token die Prüfung besteht, wenn eine Session aktiv ist und wenn eine Anmeldung gelingt. Sonst ist es None, und die Zeile endet mit einem Strich.

Eine fehlgeschlagene Anmeldung wird also mit einem Strich festgehalten, nicht mit dem Namen, der eingetippt wurde. Der Name war nicht bewiesen. Er ist Text, den ein Fremder gewählt hat, und manchmal tippen Leute aus Versehen ihr Passwort in das Namensfeld.

Diese Entscheidung hat einen Preis. Für sechs falsche Passwörter und einen weiteren Versuch zeigt das Log fünfmal POST /login 401 - und dann zweimal POST /login 429 -. Ein Betreiber sieht, dass irgendein Konto erraten wird, und nicht, welches. Ein echter Dienst hält auch den versuchten Namen fest, in einem eigenen Sicherheits-Log, das viel weniger Leute lesen können.

Schreib zuerst den Angriff

steps.bearer_for(state, "ana", "correct horse") stellt zwei Anfragen: eine Anmeldung und ein POST /tokens. Der Test ruft es auf und sichert dann zwei Dinge zu. Das Log hat genau zwei Zeilen. Und das Passwort, der Basic-Wert und der Bearer-Wert kommen jeweils nicht im zusammengefügten Text vor.

Führ python -m pytest -q aus: 1 failed, 19 passed, mit assert 0 == 2. Das Log ist leer.

Die erste Zusicherung steht aus gutem Grund da. Ein Test, der nur nach Geheimnissen sucht, würde auf einem Server durchlaufen, der gar nichts loggt.

Auch Fehler sind Ausgabe

Ein Log ist eine Sache, die ein Server schreibt. Eine Fehlermeldung ist eine andere. Wenn Python-Code scheitert, erzeugt er einen Traceback, den du in Python in der Praxis zu lesen gelernt hast. Dieser hier endet so, wie deiner in der nächsten Lektion enden wird, mit anderen Zeilennummern:

Traceback (most recent call last):
  File "reading_server.py", line 77, in handle
    response = route(request, state)
  File "reading_server.py", line 169, in route
    for book_id in state["books"]:
                   ~~~~~^^^^^^^^^
KeyError: 'books'

Er nennt Dateien, Funktionen, Zeilennummern und manchmal Werte. Für dich ist das der schnellste Weg zu einem Bug. An einen Client gesendet, ist er eine Karte vom Inneren deines Servers, ausgehändigt an den, der den Fehler verursacht hat. Der Client sollte einen festen Satz bekommen und sonst nichts:

{"error": "the server could not handle this request"}

Der Traceback gehört auf die Standardfehlerausgabe, wo der Betreiber liest. Die nächste Lektion baut das. Heute entkommt ein Fehler in route() noch aus handle().

Deine Aufgabe

1. Schreib test_attack_log_holds_no_secret() und sieh zu, wie er fehlschlägt.

2. Schreib log_line(now, request, status, user): die fünf Felder mit je einem Leerzeichen dazwischen und -, wenn der Benutzer None ist.

3. Behalte in handle die Antwort, die route zurückgibt, in einer Variablen, hänge log_line(state["clock"](), request, response["status"], request["user"]) an state["log"] an und gib die Antwort zurück.

Führ python -m pytest -q aus: 20 passed. Führ dann noch einmal python pl_sec.py other-reader und python pl_sec.py guessing aus. Jedes gibt jetzt aus, was dein Server in sein Log geschrieben hat.

Eine ehrliche Anmerkung. state["log"] wächst, solange der Server läuft. Ein echter Dienst schreibt jede Zeile in einen Stream, den etwas anderes aufbewahrt und kürzt. Diese Liste ist da, damit ein Test sie lesen kann.