My Logging Best Practices (2020)
tuhrig.de
tuhrig.de
INFO | User registered for newsletter. [user="Thomas", email="thomas@tuhrig.de"]
I think in 2020, with companies' privacy practices getting more and more scrutiny, any logging best practices doc should at least mention treatment of PII.
I found out a few years back that a large industrial device our company made was recording all users passwords due to a logging statement that was blindly just logging every piece of user input via UI.
We needed to log that kind of data during development and just tagging what messages were sensitive would have been too error prone, so we couldnt reliably have any logs once we went live.
We did however have a special crash handler that logged the exception type and callstack, but not even the exception message could touch the harddrive.
There are also a ton of tables where they made a backup copy of the table and just left it in the database for years. Ditto switching to new coce but not cleaning up the old data. So even data that would normally be removed due to, say, expiring domains ends up being preserved.
I recommend digging through it to anybody who is sad about the systems you run at work. It's such a fractal set of fuckups that I promise you'll feel better about your legacy systems.
[1] https://ddosecrets.com/wiki/Epik
[2] in PHP serialization format: https://en.wikipedia.org/wiki/PHP_serialization_format
Or passwords these people use for other services.
In this case, it is permitted to collect the log and keep them temporarily (24h or so). A workflow to keep deleting older logs or scrub the logs must be installed in this case.
Many libraries and tools support the standard now.
If you have a heavily used service, it's likely to have many concurrent requests logging into the same log stream and you absolutely need a request correlation identifier to be able to thread the log statements for a single request back together.
That's essential even if you don't actually call any other services as part of your implementation.
My problem with that is what if the program crashes or produces an error. It's good to know what the program was attempting to do.
Imagine the output
Successfully connected to DB.
Successfully read config file.
Uncaught Exception: NullPointerException
Will connect to DB...
Will read config file...
Will connect to API server...
Uncaught Exception: NullPointerExceptionIf your program disappears into a black hole doing some operation that doesn't have (and needs) a timeout specified, you want to know what it was about to do when you last heard from it.
Connecting to DB
Connected to DB → OK
Reading config file
Read config file → OK
Connecting to DB ... OK
Reading config file ... OK D: Connecting to DB
D: Reading config file
D: Connecting to API server
D: Sending updated record
I: Updated user record for $USER
E: Failed to connect to API server; could not update user record. [IP=..., ErrNo=..]In a case where there are plenty of resources and the thing you are logging is very heavy then even verbose logging is trivial.
If you are beset by failures it is much cheaper than making your developers guess.
syslog() and setlogmask() being the obvious examples.
Many (if not all) companies I have worked out filtered out everything DEBUG at compile time to improve performance in production as well.
The best option I've seen is putting everything in DEBUG or lower into a memory ring buffer per process that's dumped and collated with other logs at each ERROR/FATAL log.
Does anyone know of an implementation for this in any of the Java logging frameworks?
In my web app if nothing unexpected happens, only INFO/LOG level stuff is pushed to logs. If, however, I get an exception, I will instead print out all the possible traces. I.e. I always store all the logs in-memory and choose what should be printed out based on the success/failure of the request.
Now, of course, this is just a web API running in AWS Lambda, and I don't have to care overly much about the machine just silently dying mid-request, so this might not work for some of you, but this works great for my use-case and I'm sure it will be enough for a lot of people out there.
Or, to flip that around, if you take a program that produces a manageable amount of INFO logs, and change some of those INFOs to DEBUGs, how does that suddenly become unmanageable?
My experience has been that 1 customer-facing byte tends to generate something like ~10 DEBUG-level telemetry bytes. This level of request amplification can't be feasibly sustained at nontrivial request volumes, your logging infrastructure would dwarf your production infrastructure.
I've spent way too many hours adjusting log levels on a client environment and trying to replicate the issue without breaking or losing data while doing it.
Imagine this success output, at a low (not tracing) log level:
Opened DB connection
Opening DB connection
Opening TCP connection to 127.0.0.1:5678
Error: No more file descriptors
Error: Failed opening TCP connection
Error: Failed opening DB connection
Opening DB connection
Opening TCP connection to 127.0.0.1:5678
Starting TLS negotiation
Fatal: Segmentation fault
<stacktrace...>
Opening DB connection
Opened TCP connection to 127.0.0.1:5678
TLS negotiation completed in 0.1ms
DB version 5.1 features A, B, C
Opened DB connection
The contour around messages in between is visible (here with indentation), and the before message is not shown if there are no intermediate messages. Sometimes it's useful to show a different after-message if the before/after pair is not output, to include a small amount of information in the single message, or just to improve the language in the quieter case. Sometimes it's useful to suppress the after-message just like the before-message, if there is nothing in between.
Anything that might terminate the program, such as the Segmentation fault with stacktrace, counts as an intermediate message, and so triggers the output of all the before messages as part of the termination message logging. For this to work, of course you must have some way for the before messages to be queued that is available to the crash handler.
This is a poorly known technique, which is a shame as in my opinion it's a very helpful technique.
Its chief benefit isn't saving a few messages, it's that it scales to complex, deeply called systems with heavy amounts of tracepoints encouraged throughout the code. When studying issues, you may turn on tracing for some components and actions. As you turn on tracing for a particular component, before-messages from caller components become activated dynamically, ensuring there's always context about what's happening.
In case you're wondering, it works fine with multiple threads, async contexts, and even across network services, if you have the luxury of being able to implement your choice of logging across services, but of course there needs to be some context id on each line to disambiguate.
Exceptions should log their call stack, making both the before and after logs redundant.
Save the logs for significant events.
Edit: Good lord people, set the collector to never sample and use one of the many file exporters and you get completely bog standard logs but with a huge amount of work already done for you and enough context to follow complicated multi-threaded/multi-process programs without making your head spin.
In the simplest case you could just output a sequence of values (for example as a csv, or one json array per line), instead of an interpolated string. The size and CPU overhead of this approach is minimal, but makes it much easier and more robust to parse the log afterwards.
Such basic structured logging is quite similar to what the article proposes in "Separate parameters and messages", but more consistent and unambitious if one of the arguments contains your separator character.
If you want to preserve the "one line = one record" property typically expected from logs, standard csv will not be suitable (since it doesn't escape linebreaks), but json without unnecessary linebreaks will handle that (known as json-lines).
You almost certainly also have it in memory more than twice since you're copying a buffer out to IO.
If you care about record size use protobuf, compression, backend parsers, etc.
Of course some developers may just go ahead and create a JSON/CSV string from scratch, which is about as safe as string interpolation instead of parameter bindings for SQL statements /s. But provided they're using a proper JSON/CSV/proto object builder library that uses String references, no data is going to get copied until a logging component needs to write it to a file or a network buffer. Therefore the only overhead are the pointers that form the structure.
"$TIMESTAMP $LEVEL: Hey look index $INDEX works!"
you have
$TIMESTAMP $LEVEL $FORMATTER $MSG $INDEX
I'm quite intentionally drawing a parallel to `echo` vs `printf` here, where printf has an interface that communicates intended format while echo does not.
The only overhead of structured logs done right is that you need to be explicit about your intended formatting on some level, but now with the bonus of reliable structure. Whether you use glog or spdlog or whatever is somewhat inconsequential. It's about whether you have an essentially unknown format for your data, having thrown away the context of whatever you wish to convey, or whether you embed the formatting with the string itself so that it can later be parsed and understood by more than just a human.
If you're concerned about the extra volume of including something like "[%H:%M:%S %z] [%n] [%^---%L---%$] [thread %t] %v" on every log entry, then you use eg (in GLOG equivalent for your language) LOG_IF, DLOG, CHECK, or whatever additional macros you need for performance.
If I'm wrong or just misunderstanding, please do correct me.
With structured logging the outputs may be trivial in which case the compiler can do a good job. But if you are inserting a std::string into a log line and your log output format is JSON, there's nothing the compiler can do about the fact that the string must be scanned for metacharacters and possibly escaped, which will be strictly more costly than just copying the string into the output.
Anyway.
Isn’t the choice of eg JSON-string vs any other string format somewhat beside the point? Wouldn’t you either 1) need to scan for metacharacters or 2) NOT need to scan for metacharacters, regardless of whether your log is structured or unstructured, at time of output?
Ignoring for a moment the additional cost per character of outputting additional data, but ignoring nothing else in the scenario, wouldn’t something like, for example:
“My index is {index}␟index=5”
cost the same to output as:
“My index is 5”?
It seems to me that the cost of interpreting the formatting doesn’t need to be paid until you wish to read the log message, which presumably you don’t strictly need to do at all until you actually care about the content of the message, or at the very least can defer the cost until a less critical moment, or do some “progressive enhancement” dependent on some set of pre-requisite conditions.
Tracing is usually sampled, or much more time limited, and aggregation tooling isn't nearly as good compared to logs with most providers. Much better for deep dives into a narrow context. For a single request drilldown or aggregated performance/error metrics, tracing every time.
Structured logging tends to give you rich search against broader contexts (e.g. long spans of time, many requests in aggregate, random non performance/error attributes you may care about) without the same concerns of data cardinality.
I felt nowhere near the same power with tracing tooling for random broad context as I've had with e.g. Splunk for logs. That's not to say you can't somehow have the best of both worlds, but I haven't seen it in the ecosystem just yet.
There are a few concepts to understand, but instrumenting it right from the start is valuable as it grows into a bigger system. Being a cross-cutting concern, the more code that standardizes on this the more useful it will be.
That may be the case, however is what you have now is "logging", I would 100% recommend the incremental upgrade to "structured logging".
I would not put an email address in logs, but definitely some kind of account identifier so that we can investigate bug reports from specific users.
In general I set the bar for “ too much logging” very high. It’s a better problem to have too much log to store and sift through vs having no data.
It won't be nearly as convenient to dig that fact out, though.
1) shout out to https://github.com/RehanSaeed/Serilog.Exceptions
It is an extension of the «but it worked on my laptop» mentality.
No, it won't work in a complex environment, specifically in a scenario where a server farm sits behind a load balancer with a VIP (geographically distributed or not), which is ubiquitous. Specifically, it won't work in a situation where a server instance the application attempted to connect to sits in a subnet in another data centre across a WAN link, and the networks put a shoddy firewall rule in last night or applied a bit rotten firmware patch to the router, and new server connections suddenly started getting TCP resets halfway through the data exchange. You won't know which particular service instance the resolver ended up resolving and connecting to unless you have a "before" log entry as well. Hiding the dead horse in the cloud will help in a serverless or in a simple scenario, but, if you have a load balancer and multiple availability zones, you still have the same problem, due to cloud load balancers failing over to another AZ at will (it is more nuanced than that, though).
Logging inputs is as critically important as logging preceding statement's outcome, albeit it has to be used wisely as excessive and, worse, not properly structured log entries can (and will) overwhelm the log sink in a high data volume environment. Log ring buffers can be a solution for some cases, and a monitoring component that is integrated into an app can be an answer in some other cases, but there is no single, one size fits it all, solution for an arbitrary setup in a high data volume environment.
This is a given, it's typically done by "add the library, one line of code at startup to enable it"
While this technically qualifies as "Logging inputs before" it does not seem to be what the author is talking about. I was assuming that was present, and had been reached - cause if it had not, what request are you even debugging? Rather than some "«but it worked on my laptop» mentality" straw man.
It feels more natural to log when something is complete instead of constantly saying when you're starting to do something, but it leads to issues where you have no idea what the system was actually doing when it failed. It's very easy to have the process die without logging what made it die, especially if you're using a language that doesn't provide stack traces or you have them turned off for performance.
Logging before an action also means it's possible to know what's going on when a process hangs. It might lead me to where I should look to resolve the problem instead of forcing me to just restart the service and hope for the best.
The power of structured logging here is in enriching events to make them queryable later, so you could e.g. view all events for a request.
Which is pretty good practice because when things go wrong in Prod, you want your logs to tell you quickly what went wrong. Too many times I have seen that something goes wrong in Prod and then people say "Oh we should have logged that"
I tried this recently by accident, and the drawback of that approach immediately became apparent:
The logs will be very difficult to read, because for nested function calls, low-level callee functions will log before high-level caller functions, and you have no idea why they are called until later:
Finished string comparison of length 4
... 200 more lines...
Finished string comparison of length 2
Finished Boyer-Moore string search
Finished searching for example.com
Finished searching for disallowed domains
Finished checking email address
Finished logging in user
There's nothing stopping you from adding "Begin User Login" logging calls if you want to make the nesting more explicit. If you no idea why stuff is being called, it's only because you have unlogged branches in your code.
and it is way better than reporting success when it hasn't actually happened.
I'd say this is good for production. During development, I sometimes like to log the name of the function I'm in as the first line of the function. That way I'm assured to know if the function was even called. I will also put before and after logs if I want to see how data is changed (Yeah, there are things called debuggers that let you watch variables, but sometimes a log is just so much easier - such as in heavily threaded code or code with a number of timers and events firing).
> I make exceptions for DEBUG.
Sharing a few things briefly below I have learned over the past few years -
1. Log every single message for a transaction/request with the requestId to look at the entire picture. Ideally, that requestId would be used upstream/downstream too internally for finding exact point of failure in a sea of micro services. 2. Log all essential id's/PK's for that particular transaction. - makes debugging easier. 3. Log all the messages possibly in a json format, if the log aggregator you are using supports that. Parsing later for dashboards makes lives WAY EASIER and is more readable too. Might also reduce overall computations being run on the cloud to extract values you want -> hence, lesser cost. 4. Having error/warn logs is good, but having success/positive logs is equally important imo. 5. Oh, and be very very careful about what you end up logging. We don't want to log any sort of user PII. At one of my previous companies, there were mistakes made where we were logging user's phone numbers, addresses etc.
I am sure the community here already knows about these, and might have even more to add. Would love to hear what other people are doing.
Cheers.
With info and success level you could log info before and success after execution.
In dev mode you show info, in production you could filter success.
His suggestion is to accumulate verbose messages in memory/disk, so we can later decide whether to dump them out (e.g. in a top-level error handler).
The talk suggested an SQLite DB, with dynamically-configurable filters for what to keep, etc. but that's a step beyond ;)
Interesting; I've definitely seen that with unit test frameworks. Where in addition to assertEquals(...) there was an annotate(...) method which just took a string, and was stored for that unit test. If the unit test eventually failed, all the previous annotations for that unit test were printed, otherwise they weren't.
https://metacpan.org/pod/Test::Unit::TestCase#annotate-(MESS...
Structured logs (of course structured) in a simple text file. Rotate the files if your antiquated system cannot handle big files or if you wildly successful crypto currency scam generates many many gigabytes a time period.....
`grep` is your friend!
The accumulate-then-dump idea doesn't require any database though; just an in-memory buffer (e.g. a linked-list). For example, we can have all ERROR/WARNING/INFO messages output immediately, as is current practice. The difference would be for DEBUG messages:
- Common practice is that if DEBUG is set then we'll output DEBUG messages as they're encountered; if DEBUG is not set then we'll skip over them.
- The suggestion is that if DEBUG is not set, then instead of skipping messages the logger would put them in a buffer. If an unrecoverable error occurs, we can put a call like `logger.dumpDebug()` in the handler, so all those DEBUG messages will appear in the logs to help us diagnose the error. If no error occurs, the buffer just gets discarded.
This obvious takes more memory, but fits well with a request/response setup like a server. Long-running applications/games could either use a ring buffer, or identify points where it makes sense to empty the buffer.
Getting an error like "this thing fell over because of a number parsing error" might not be very useful when you can't recreate it.
With correlation, you then realise that the user did something specific beforehand and then the cause is more obvious.
I think the more practical advice is "buffer logs outside your application" or "buffer logs in a separate thread/process that crashes independently of your application code."
Even the small places I've worked could easily push 250G logs a day.
(Without shared memory, I imagine you'll have one system call per log anyway - in which case it's not much different from calling one write() per line.)
If for some reason you can't easily figure out whether something succeeded, you should probably log before and after the operation. I personally try to avoid doing this since it can clutter up the log, but it can be useful depending on how code is structured.
Another minor point is that I prefer to have INFO cram as much information as possible with DEBUG reserved for stuff which is ignored unless you explicitly turn it on either due to lack of utility vs cost.
This is already weird, what about operations that take a long time? If the session is interactive, the user should definitely know that nothing hung up. Or is it out of scope somehow?
Since you generally only want to see them when diagnosing a frozen job or something equally obtuse.
using(_log.TimeOperation("Doing the thing"))
{
DoTheThing();
}
Author doesn't seem to have reached that level of best practice yet.
You don't need to log every method call, every variable, every "if" statement, ect. That's what the debugger is for.
And, I shouldn't need to say it: Don't log passwords or other sensitive information.
Also: Make sure your logger is configured correctly. Log4Net used to (and it still might) calculate an entire stack trace with each call to the logger. It can be the single highest consumption of CPU in an application; even if you aren't actually logging stack traces.
Lambdas don't have debuggers afaik. So, verbose logging is the simplest (only?) way out. Probably not at the "let's log every action" level but I find myself erring on the side of logging more rather than less.
Remember that just because you love to hear what your application is doing, it's not always be helpful or useful to your user. Give consideration to the Rule of Silence (http://www.linfo.org/rule_of_silence.html) and even if you do not agree with it remember that some of your users might.
Instead, to figure out how well a complex system is running, you need to monitor continuous values. Things like flow volume across boundaries, level or volume in buffers or storage, composition of things as fractions of the whole, and so on.
Other industries (nuclear, aeronautics, oil and gas, electricity) know this already, but us software engineers have been slow to pick it up.
That resonates entirely with me, but I still have trouble putting it into practise. Does anyone have references to stuff written about this?
Sounds expensive. I'd say logging in IT hasn't been as advanced because the tradeoffs most software projects chose are very different from requirements of nuclear, aeronautics, etc.
We used that as a standard for logging for at some point, it has some pretty good insights.
An elevated number of WARNs indicates a problem. So this is a metric we monitor. And obviously ERRORs since that means there is a problem.
I guess though you can write explicit thrown error messages too. It's just throwing and catching seems more annoying and indirectional compared to the events.
The MDC can be honored with Multithreading too.
[1]: https://pinecoder.dev/blog/2020-04-27/node-exit-logging
In production, if you set to warn only, will you have enough data? If you set to info, will you have too much?
- Always log errors
- Don't log errors twice (log or rethrow)
Don't throw exceptions for auth failures.
Consistency in how you log is probably Best Practice #0, IMO.