Logging Literacy
tldr;
Log your story. Log date, category/facility, level, message. Log like you’ve never log before.
If you’re coder who doesn’t care about debugging stuff on a production system, first and foremost, I don’t want you on my team, second, log statements are most likely not your concern. Otherwise, log statements is your trail into finding root cause of issues. You need to track that bitch down, digging through a pile of logs and you need to converge fast. To do so, you need to have enough log statements for it, baring the maximum information, yet in a processable format. More and more, logs tend to become the blood of analytics system.
Log statements are crucial. I like having nice looking logging statements. Logging statements are language statements: syntactically right, starting with a capital letter, ending with a period. Date, category/facility, log level, message. I like having the ability to read log files as a cinematic stories, where we have a good prologue of the form “[12345] User created.”, a more dramatic touch with “An error occurred while parsing input from [/var/spool/foo.json].”, where you can always have in mind the actual plot line for a given sessionid, transactionid, or hum, callid (I’m in the telecom).
It’s all about context.
It all starts with a timestamp. Well, an ISO 8601 date. Adopting a standard means it is most likely machine readable, parseable and so on (Did you know you can use straight “ISO8601” as a PatternLayout within LogBack?). Adopting a standard also means homogeneity, and while digging logs, your eyes look for patterns.
Then follows your category or facility. A classname, a module, or proc name. Something that indicate where this piece of information is coming from.
Log level as a focus or depth indicator. At WARN, I should still be able to read your story, like a short story. While DEBUG gives me the full story and reads like a novel, TRACE gives me the full movie scenario narrative and all. Most likely too much unless you’re the director or an actor.
Last but obviously not least, comes the message itself. A somewhat free form statement of your activity, as part of your dialogue. While statements like “Houston, we have a problem.” (True story) may sound funny at first, it it less so during late night root cause analysis. While developing, I like keeping my log console next to my continuous testing status. Output from my logs are insights into my development workflow as I progress. Constantly adjusting the output, adding bits here and there. It would be tempting to remove those, cleanup after oneself once we are satisfied with our work. Don’t do it. As precious as it is while developing, as precious it gets during a debugging session. Just use the appropriate level and defer string evaluation.
Considerations for log aggregation and streaming: it may be worth considering adding an IP to your log statement whenever your logs are candidate for remote aggregation, like syslog for instance (see RFC 5424). Although log statement can be altered and transformed in-transit through log agents/collectors facilities.
While I don’t have any first hand experience in such approach, some people are formatting log statements as json string. While the log agent can do part of the job, the idea for a better and richer machine readable format upfront is nonetheless tempting. grep, cut, xargs, sed, and awk are all valuable tools but it’s hard to beat a rich model indexing and queries. But that’s another story maybe worth exploring later.
A special case for error/exceptions: on error/exception, if you throw back, don’t log.
Anti-Patterns
- No or so little logs…or invalid use of log level.
- No context or useless statements.
- “Invalid user ” or “invalid user [].”? Can you better spot the empty userid string?
- “Entering methodxyz” … “leaving methodxyz”. Those are just plain annoying. Again give me context: “Creating user [abc].” … “User [abc] successfully created.”
There’s an adage that I’m trying to pass on to my peers: “Log like you’ve never log before.” That, and to use tail -F instead of tail -f.
