TT Lab
Get started
Learn Learning paths Courses

Envoy Internals

You Can Only Fix the Format Beforehand

Continue in TT Lab

In one line

An access log is not a switch you turn on and off; it is the work of designing a format. You decide four things: what to record (command operators), in what shape (text or JSON), where to record it (the sink) and what alone to record (the filter), and if you have not decided them, all that is left after an incident is 200 GET /.

Why this was needed

The first things you ask when an outage hits are always the same. Who requested what, where did it go, how long did it take, and why did it fail? If you can answer these four from one log line, you narrow down the cause within minutes. If you cannot, you dig through application logs, and if those are missing too, the guessing begins.

The problem is that you have to decide this format before an incident. Even if you realize after an incident "I should have recorded the upstream address too", it is already not in the log of that incident. That is why the access log is the only part of the observability configuration that is irreversible.

How it works

Command operators. A %...% in the format string means one value. Picking out just the commonly used ones, it is about this.

Operator What
%RESPONSE_CODE% Status code
%RESPONSE_FLAGS% The short cause marks Envoy attaches (UT, UF, NR and so on)
%UPSTREAM_HOST% The address and port of the upstream that actually received it
%DURATION% Milliseconds the whole request took
%BYTES_SENT% Number of bytes sent out
%REQ(이름)% · %RESP(이름)% Request and response headers (the placeholder is the header name). If it starts with a colon, like :METHOD, it is a pseudo-header

When there is no value. For a response that did not go to an upstream (direct_response), there is no value to put in %UPSTREAM_HOST%, and the same goes for a header that was not sent. Envoy does not leave that spot empty and fills it with a fixed mark. If you mistake this mark for a real value when reading logs by machine, your aggregation goes quietly wrong.

Text or JSON. Text cut by a separator is easy for people to read, but the moment the separator appears inside a value, the fields shift. If you plan to send it to a collector and query it, json_format is better from the start. You can name the keys freely, and you use the same operators in the value slots.

Sinks and filters. access_log is a list, so you can have several, and each has its own format and its own filter. A filter can be set on status code, duration, response flag or header conditions. The most common setup in practice is to keep the full log short and the error log detailed and separate. If you mix them in one file, you cannot set the retention period separately. One syntax trap that catches people here — filter goes outside typed_config, not inside, at the same level as name.

What it looks like in the field

"The log is not being written." A file sink does not write to disk on every request. It gathers in a buffer and empties it periodically, and the default period is 10 seconds (--file-flush-interval-msec). If you cat right after a request, it is normal for it to be empty. If the container dies right away, the buffer really does disappear with it, so in a short-lived sidecar, lower this value or send to standard output.

When logs fill the disk. The access log is the only observability signal that grows in proportion to traffic. At thousands of requests per second, it reaches tens of gigabytes a day. So keep the format short and use the detailed format only on a sink that has a filter.

When logs are sent to standard output. In container environments, a setup that gives /dev/stdout as the path instead of a file is common. The collector is already scraping container logs, so you ride on that path. But then application logs and access logs get mixed into one stream, so you need to put a mark that tells the two apart in the format, to be able to separate them later. And standard output clogs before a file does — if the receiving side slows down, that pressure climbs up to the proxy.

What happened when we trusted the request ID. The request ID is the thread that ties together one request passing through several services, and the proxy at the very front creates a value if there is none and passes it along as it is if there is one. That also means anyone outside can send in any value. At the spot where traffic comes in from outside the trust boundary, it is safer to delete this header and create it fresh.

Official documentation: Access logging · Command line options

What you will do in the next lab

You turn on a file sink and confirm why the log does not show up right away, then design an eight-field format and record three kinds of requests. You see for yourself what is printed in the slot where there is no value, switch to JSON format and read it with jq, set up a separate sink that keeps only 500 and above, and finally confirm how it differs when the client gives a request ID and when it does not.