- date
- entry
- 015
- topic
- delivery
- rev
- —
Your access log cannot answer "why"
You pull the 500 out of the log and the line gives you method, path, status, latency. The real error message is a few lines above it — and you cannot say which few, because twenty other requests were writing during that same second.
A typical access log line:
[GIN] 2026/09/07 - 21:03:11 | 500 | 142.7ms | 10.0.1.24 | POST /api/v1/orders
It tells you the request happened, that it failed, and that it took 142 milliseconds. It does not tell you the one thing you want: why.
The reason is who writes it. An access log is emitted by middleware after the handler returns, so what
it can see is the response: status, size, duration. The contents of that err
inside the handler stopped existing at the return, unless somebody wrote it out
separately.
Two logs, both correct, unable to meet
Most services do have both. The error message usually was printed — a few lines above the access line:
ERROR: pq: duplicate key value violates unique constraint "orders_trade_no_key"
[GIN] 2026/09/07 - 21:03:11 | 500 | 142.7ms | 10.0.1.24 | POST /api/v1/orders
At low traffic that is enough; you pair them by ordering. The method stops working under load, when twenty interleaved requests are writing in the same second and "a few lines above" becomes a guess.
Two logs that are each correct but cannot be joined are worth close to nothing together.
Request id: one thread through it all
The fix is not logging more. It is giving each request an identifier and carrying it on every line.
Middleware at the edge generates one, or reuses what came in:
func RequestID() gin.HandlerFunc {
return func(c *gin.Context) {
id := c.GetHeader("X-Request-ID")
if id == "" { id = uuid.NewString() }
c.Set("request_id", id)
c.Header("X-Request-ID", id) // hand it back to the client
c.Next()
}
}
Then every line — errors, warnings, the access line — carries that field:
{"level":"error","request_id":"7f3a…","msg":"insert order failed",
"err":"duplicate key value violates unique constraint"}
{"level":"info","request_id":"7f3a…","status":500,"method":"POST",
"path":"/api/v1/orders","latency_ms":142.7}
Investigating a 500 is now a query rather than an excavation: filter by request id and you have the complete story of that one request.
Do not skip handing the id back to the client. It turns "a customer reported a
problem" from a vague description into a key you can look up directly — they attach the
X-Request-ID and you never have to ask what time it was, which account, how many
attempts. Same habit as
putting the build sha in a response header: place the
diagnostic information inside the thing users already copy to you.
Reuse the upstream id
Notice the middleware reads X-Request-ID before minting one. That is what lets the id
cross services: the frontend generates it, the backend adopts it, and passes it along when calling the
next service.
Without that, one request through three services produces three unrelated ids and you are back to guessing by timestamp. It matters most in exactly the situation from debugging a multi-layer system — "how far did the request get" becomes a single query when everyone shares the id.
Structured, because you query it rather than read it
Plain text is friendly to grep and unfriendly to "every request in the last hour with
status ≥ 500 whose path starts with /api/v1/orders". Emitting JSON so fields can be filtered is cheap
while the log volume is small and expensive to retrofit at the moment you need it.
The minimum set of fields:
request_id,timestamp,levelmethod,path,status,latency_ms- the error line's
err— the original message, not "operation failed" - identity (an internal
user_id, not an email address)
What must not go in
Access control on logs is usually looser than on the database, so some things are leaked the moment they are written:
- Tokens, passwords, API keys — including the time you printed one "just to debug". The if it appeared, it leaked rule applies here too
- Whole request bodies — eventually one contains personal data or a card field. If you must log them, use an allowlist, never a blocklist
- Personal data — email, phone, address, national id. Log an internal id and look the rest up when you need it
The awkward part is that it is irreversible: a written log has already spread to your log service, your
backups, and someone's downloaded .log file. You cannot delete it back out.
While you are there, set retention. CloudWatch log groups default to keeping data forever, and they bill by stored volume. Set a retention period during delivery — thirty to ninety days suits most services — or in two years you will meet a puzzling line item covering logs nobody ever queried.
If you remember one thing
The value of logging is not how much you write, it is whether you can get from a symptom to a cause. There is one test: given a single failure a user reported, can you see everything that happened during that request in one query? If not, more lines only consume disk.
Revision history
- First published