For the longest time, I've done the bare minimum and just used console.log/print for whatever I thought I needed in that particular piece of code; without any coherent system.
> For a web service, that usually means one log event at the end of every request.
The point of a log, as I have seen it used, is to understand what's going on during a request. Yes, some of that is timing / success / failure information, but you also need:
- Logical tracing - at a high level, what decisions did we make (authz, business logic) when serving this request
- Partial failures or warnings - the request may have succeeded, but we may have failed or timed out a call to a dependent service and delivered a partially degraded response as a result
- Tracepoints to support active development - how often do we hit a certain codepath (to help developers roll out or deprecate features)
It's useful to distinguish between "context" (things we know about a request), timing, success, and plain old logging (using human language to describe to an operator what the system is doing). Context should be included with every line - I strongly agree with OP's proposal of wide events, don't make operators ever JOIN if you can avoid it - but it won't always be the same because we learn things about the request as we process it. Yes, if you wait until the end of a request, you will have maximal context, but at the loss of fine-grained detail during processing.
I completely agree with your plain-old logging list. I would add canonical log lines in addition to the normal log traces. They serve as the summary at the end.
It does help that the system was built from the ground up to use the big logs.
I think the best feature was that we would extract and build a ton of keys into the full-size log, so you could find all transactions related to X really, really easily, where X was a wide variety of things.
Every place I’ve been elsewhere the logs have always been way harder to parse, process or even just find. It would always take several disparate queries to get everything.
E.g. “oh, we need to find something related to X? Well okay, that gives us 50 different separate calls, now let’s do another search on each of those calls’ unique transaction id and review each whole transaction individually” vs “I need X. Cool, here’s all 50, complete calls.”
Edit: to be clear, throughout the code it was just “context.info()”, over and over again, like regular logging, it was just shoved into a big object at the end of all non-application-crashing exceptions. And the application was built to not fully crash, like, ever. (And this worked)
The idea is to consolidate all that can be grouped into one logical unit. So you would do one long log line at the end, after all tasks are done.
