Logs and Errors Without Secrets

ben tried to delete ana’s book and got a 404. Six wrong passwords for ana ended in a 429. Who would ever know? Your server refused both and kept no record of either.

A server that refuses needs to write its refusals down. And what a server writes down is read by more people, and kept for longer, than almost anything else it produces: operators, support staff, backup systems, whoever is handed a file to look into a problem. A log is the easiest place to leak a secret that every other part of the server guards.

What never goes in a log

• The Authorization value. For a login it is a password in base64. For a book request it is a token that works for 15 minutes.

• A cookie value. A session id is the credential once login is over.

• A password or a token in any other form.

• The query string. Tokens, email addresses, and search words end up there.

Python has a logging module for real services. This course does not use it. Here the log is a list of text lines in state["log"], so that a test can read it.

Five fields

One request, one line, five fields with one space between them: the time in whole seconds, the method, the path, the status, and the user. With the clock fixed at 1000000, ben getting a token, trying to delete ana’s book, and someone failing a login look like this:

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) returns such a line. int(now) drops the fraction of the time. request["target"].partition("?")[0] drops the query: partition splits text at the first ? into three parts, the text before it, the ? itself, and the text after it, and [0] is the first part. When there is no ?, the first part is the whole text.

Why not urlsplit, which you used in HTTP with Python? It parses the whole target, and some targets it refuses with an error. urlsplit("http://[") raises ValueError. A log line is written for every request, the strange ones too, so the code that writes it must not be able to fail. partition works on any text.

The path as it arrived

Log the path exactly as it arrived, still percent-encoded. Do not decode it.

A path may contain %0A. Decoded, that is a line break, and a line break inside a log line starts a new line. A stranger could then write a second line of their own choosing into your log, one that looks like a request that never happened. Kept encoded, %0A is three harmless characters.

This is a first look at a pattern that all of Chapter 7 is about: text from a request that ends up somewhere it is read as structure.

The fix has a limit. Other control characters can still reach a method or a path, and a real log also escapes those before it writes a line.

Whose name

The fifth field is request["user"]. The project sets it in three places: when a token verifies, when a session is live, and when a login succeeds. Otherwise it is None, and the line ends in a dash.

So a failed login is logged with a dash, not with the name that was typed. The name was not proven. It is text a stranger chose, and people sometimes type their password into the name field by mistake.

That choice has a cost. For six wrong passwords and one more attempt, the log shows POST /login 401 - five times and then POST /login 429 - twice. An operator sees that some account is being guessed, and not which one. A real service records the attempted name too, in a separate security log that far fewer people can read.

Write the attack first

steps.bearer_for(state, "ana", "correct horse") makes two requests: a login and a POST /tokens. The test calls it, then asserts two things. The log has exactly two lines. And the password, the Basic value, and the bearer value are each not in the joined text.

Run python -m pytest -q: 1 failed, 19 passed, with assert 0 == 2. The log is empty.

The first assertion is there for a reason. A test that only searched for secrets would pass on a server that logs nothing at all.

Errors are output too

A log is one thing a server writes. An error message is another. When Python code fails, it produces a traceback, which you learned to read in Python in Practice. This one ends the way yours will in the next lesson, with other line numbers:

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'

It names files, functions, line numbers, and sometimes values. For you that is the fastest way to a bug. Sent to a client, it is a map of the inside of your server, handed to whoever caused the error. The client should get a fixed sentence and nothing else:

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

The traceback belongs on standard error, where the operator reads. The next lesson builds that. Today an error inside route() still escapes handle().

Your task

1. Write test_attack_log_holds_no_secret() and see it fail.

2. Write log_line(now, request, status, user): the five fields with one space between them, and - when the user is None.

3. In handle, keep the response that route returns in a variable, append log_line(state["clock"](), request, response["status"], request["user"]) to state["log"], and return the response.

Run python -m pytest -q: 20 passed. Then run python pl_sec.py other-reader and python pl_sec.py guessing again. Each now prints what your server wrote in its log.

One honest note. state["log"] grows for as long as the server runs. A real service writes each line to a stream that something else keeps and trims. This list is there so that a test can read it.