7 ms·

> Log after, not before 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. Ima

> Log after, not before 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 vs. Will connect to DB... Will read config file... Will connect to API server... Uncaught Exception: NullPointerException

jayknight 5y ago
I think he is assuming that the logged exception will include the details needed to track down the error (line number, stack trace)
- adrianmsmith 5y ago
  Of course in an ideal scenario that's the case. Nevertheless programs do sometimes just "crash" without an error message, or maybe they hang and never produce any output due to an infinite loop, or excessive memory allocation and GC overhead, etc. Logging what the program was attempting to do is useful in those scenarios.
  - sagichmal 5y ago
    Yes, it’s useful, but that occasional usefulness is substantially outweighed by it’s perpetual cost.
- bobbyi 5y ago
  Yes. I think logging before is still useful, but it is for hangs, not exceptions. If 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.
spaetzleesser 5y ago
Agreed. Logging before gives you a lot of information to diagnose an issue. Logging just exceptions usually lacks a lot of necessary information
- goohle 5y ago
  Just print out all necessary information, in case of exception, and suggest a potential solution to the problem.
  - slaymaker1907 5y ago
    This does not work in practice a lot of the time. What if the problem was actually due to some other thread and said other thread didn't crash? If you only log after success/failure, you would have absolutely no idea why the program crashed. Oftentimes if the actual error were anticipated enough for good reporting, said error would not exist in the first place.
BrandoElFollito 5y ago
I prefer to have both information (the actual logs would be structured) Connecting to DB Connected to DB → OK Reading config file Read config file → OK Even better, but hardly doable because of the nature of logging Connecting to DB ... OK Reading config file ... OK
- kulikalov 5y ago
  Performance though?
  - worik 5y ago
    Diagnosis of failure?
raldi 5y ago
That's what the DEBUG level is for, as explained at the end of the section you're referring. So it would be like: D: Connecting to DB D: Reading config file D: Connecting to API server D: Sending updated record I: Updated user record for $USER Or, if it fails, the last line is replaced by: E: Failed to connect to API server; could not update user record. [IP=..., ErrNo=..]
- theshrike79 5y ago
  The log file should, by default, have all necessary info to debug the issue - or at the very least enough information to narrow down the problem so far that you can replicate it locally. 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.
- dezzeus 5y ago
  Even though it can be lost by an optimistic configuration, I prefer to use the TRACE level(s) and leave the DEBUG one for, well, debugging.
  - raldi 5y ago
    We're discussing a NullPointerException situation; how is that not debugging?
    - Leherenn 5y ago
      I think OP's case was not debugging a crash, just that if a crash happens he would like the log to be before rather than after. The log statements would be there no matter whether there is a crash or not, just in case.
- yongjik 5y ago
  Personally I'm not a fan of DEBUG level (unless you always keep it on). You can have a transient system issue that appeared for 30 minutes and then went away. If DEBUG logs weren't turned on at the time, they won't help me.
jlokier 5y ago
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.
- psd1 5y ago
  Got any example implementations? "Dynamic logging" isn't a great search phrase
AlexCoventry 5y ago
Would it make sense to log a traceback, on unexpected errors?
Too 5y ago
Generally agree but this also leans a bit towards printf-debugging. Exceptions should log their call stack, making both the before and after logs redundant. Save the logs for significant events.

jayknight 5y ago

I think he is assuming that the logged exception will include the details needed to track down the error (line number, stack trace)

adrianmsmith 5y ago
Of course in an ideal scenario that's the case. Nevertheless programs do sometimes just "crash" without an error message, or maybe they hang and never produce any output due to an infinite loop, or excessive memory allocation and GC overhead, etc. Logging what the program was attempting to do is useful in those scenarios.
- sagichmal 5y ago
  Yes, it’s useful, but that occasional usefulness is substantially outweighed by it’s perpetual cost.
bobbyi 5y ago
Yes. I think logging before is still useful, but it is for hangs, not exceptions. If 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.

spaetzleesser 5y ago

Agreed. Logging before gives you a lot of information to diagnose an issue. Logging just exceptions usually lacks a lot of necessary information

goohle 5y ago
Just print out all necessary information, in case of exception, and suggest a potential solution to the problem.
- slaymaker1907 5y ago
  This does not work in practice a lot of the time. What if the problem was actually due to some other thread and said other thread didn't crash? If you only log after success/failure, you would have absolutely no idea why the program crashed. Oftentimes if the actual error were anticipated enough for good reporting, said error would not exist in the first place.

BrandoElFollito 5y ago

I prefer to have both information (the actual logs would be structured) Connecting to DB Connected to DB → OK Reading config file Read config file → OK Even better, but hardly doable because of the nature of logging Connecting to DB ... OK Reading config file ... OK

kulikalov 5y ago
Performance though?
- worik 5y ago
  Diagnosis of failure?

raldi 5y ago

That's what the DEBUG level is for, as explained at the end of the section you're referring. So it would be like: D: Connecting to DB D: Reading config file D: Connecting to API server D: Sending updated record I: Updated user record for $USER Or, if it fails, the last line is replaced by: E: Failed to connect to API server; could not update user record. [IP=..., ErrNo=..]

theshrike79 5y ago
The log file should, by default, have all necessary info to debug the issue - or at the very least enough information to narrow down the problem so far that you can replicate it locally. 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.
dezzeus 5y ago
Even though it can be lost by an optimistic configuration, I prefer to use the TRACE level(s) and leave the DEBUG one for, well, debugging.
- raldi 5y ago
  We're discussing a NullPointerException situation; how is that not debugging?
  - Leherenn 5y ago
    I think OP's case was not debugging a crash, just that if a crash happens he would like the log to be before rather than after. The log statements would be there no matter whether there is a crash or not, just in case.
yongjik 5y ago
Personally I'm not a fan of DEBUG level (unless you always keep it on). You can have a transient system issue that appeared for 30 minutes and then went away. If DEBUG logs weren't turned on at the time, they won't help me.

jlokier 5y ago

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.

psd1 5y ago
Got any example implementations? "Dynamic logging" isn't a great search phrase

AlexCoventry 5y ago

Would it make sense to log a traceback, on unexpected errors?

Too 5y ago

Generally agree but this also leans a bit towards printf-debugging. Exceptions should log their call stack, making both the before and after logs redundant. Save the logs for significant events.