Hacker News Reader

Comment by adrianmsmith | Hacker News Reader

> 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

View on HN

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=..]

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.

We're discussing a NullPointerException situation; how is that not debugging?

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.

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.

Why not have the program write logs to a temp file somewhere at trace/debug level, and only output the standard level to the console?

Wouldn't that end up slowing down the whole system from writing to a file though?

Ah, suppose it depends on how much you're doing and/or how verbose your logs are. If you've got lines speeding past then yeah I maybe wouldn't write them all.

Writing verbose logs is very expensive.

It depends which costs what.

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.

Of course you always keep it on — the point of the different levels is that you can filter them out at read time (e.g. to eyeball logs, or to alert when the rate of >= WARN is too high)

This traditionally has not been log level's use case.

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.

That is actually quite nifty. That way you can carry debug logs and only materialise/send them in case of errors when you are likely interested in it without having to put those logs at error and see them all the time etc.

Does anyone know of an implementation for this in any of the Java logging frameworks?

Fwiw sentry does that out of the box, anything below warning (I think) is used as context for “actual events”.

I've actually used this idea in production and it worked great.

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.

Performance degradation is noticeable with DEBUG level in production.

Performance degradation is noticeable with excessive logging; the level is irrelevant.

Leaving debug levels on in production will bankrupt most companies.

Addressed here: https://news.ycombinator.com/item?id=28764834

Nope, this produces unmanageable log volume.

How does making these DEBUG logs into INFO logs make the volume manageable?

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 point is that DEBUG level logging is (hopefully!) not on by default, and that this is what it makes the production log volume manageable.

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.

Debug was not designed to always be left on. That's why you need to enable it in the first place.

Debug level is not for production, it's for debugging.

Have you never needed to debug an issue that was only happening on production?

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.

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

Performance though?

Diagnosis of failure?

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

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.

Yes, it’s useful, but that occasional usefulness is substantially outweighed by it’s perpetual cost.

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.

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.

Got any example implementations? "Dynamic logging" isn't a great search phrase

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.

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

Just print out all necessary information, in case of exception, and suggest a potential solution to the problem.

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.

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

Reply on news.ycombinator.com