Re:My Logging Best Practices (2020)
by jlokier on Tuesday October 05, 2021 @01:48PM
(#28762909)
I've found the most useful log before/after pattern is a little-known dynamic variant.
Imagine this success output, at a low (not tracing) log level:
Opened DB connection
Error output at the same logging level:
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
Crash output at the same logging level:
Opening DB connection
Opening TCP connection to 127.0.0.1:5678
Starting TLS negotiation
Fatal: Segmentation fault
<stacktrace...>
Success output with tracing turned up and no error:
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 key feature here is that there's a scoped before/after message pair ("Opening DB connection" and "Opened DB connection"), and the before part of the pair is output if and only if any messages are output in between.
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.
Imagine this success output, at a low (not tracing) log level:
Error output at the same logging level: Crash output at the same logging level: Success output with tracing turned up and no error: The key feature here is that there's a scoped before/after message pair ("Opening DB connection" and "Opened DB connection"), and the before part of the pair is output if and only if any messages are output in between.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.