There’s an additional benefit to the author’s usage of square brackets in the “Separate parameters and messages” section: should the variable ever be empty, for whatever reason, then seeing a pair of empty brackets in the logs is very helpful in determining potential issues. I’ve wrapped mine in single quotes preceded by a colon for quite some time now and it’s been extremely useful.
Another helpful thing I’ve discovered is using logfmt right from the start as when you need to process the logs by something that natively supports ‘logfmt’ then you don’t have to go back and start making changes to the logging code nor writing any complicated parsing rules for your existing logs.
I agree with all but the first. While debugging I have often found myself going through code and moving debug log statements from after to before. The reason is that if there is a catastrophic failure you want to know what was being attempted at the time.
If you have something like
initialising content service
initialising config service
-- crash --
you know what module to look at, but if it is just
initialised content service
got image 1
-- crash --
then it is difficult to diagnose. Was there an image2? What module is loaded after content service?
Before people respond with the usual ‘you should have a stack trace’ or ‘if you are logging properly you will know anyway’ the times when I have needed this are when working with large legacy code-bases or trying to extend very large complex software that is opaque and badly documented in ways that were not envisioned by the original developers (read game modding). Yes in a perfect world you wouldn’t ever be left with a log that just ends without warning, or a totally opaque and incomprehensible error message. But if we lived in a perfect world we wouldn’t need logs for debugging because we would have no bugs.
With regard to the reason given in the article for this rule, “When reading it, you will not know if the REST call was successful or not” - If it is important to know if an action succeeded you should have an explicit succeeded message in the log in addition to the general progress reporting message. In the example from the article, if the REST call fails you will not get any output from that line if an exception is thrown, meaning you not only don’t know if the call succeeded, you don’t even know if the call was attempted. If no exception is thrown you will get “Made request to REST API” which does not tell you it failed.
The author does mention that they don’t enforce this rule for debug logging.
Log messages should definitely have a format that’s easily grokkable; I think backend engineers often overlook this and want to write sentences instead. Great read.
This is excellent. There’s a surprising amount of this fundamental and hard-earned knowledge that we expect people to just sort of “pick up” over time without having it written down. This is where I think seasoned engineers can make a huge impact. Even seasoned folks will have better reasoning around why we hold these opinions and what the underlying values are - I know I will.
It’s a shame centralised logging is only mentioned in passing at the end. Even if you only have one machine running the code, having the logs shipped off in a way that they cannot be changed to another server is invaluable. Being able to see all of your logs on one screen as they’re being generated chronologically will bring a lot of context to what is going on.
Also, if you lose access to a machine, you can see if it’s still working, and what was happening in the lead up to losing access.