Should I log before or after an operation?

Question

I'm thinking about where to write the log record around an operation. Here are two different styles. The first one, write log before the operation.

Before:

log.info("Perform operation XXX")
operation()

And here is a different style, write the log after the operation.

After:

operation()
log.info("Operation XXX is done.")

With the before-style, the logging records say what is going to do now. The pro of this style is that when something goes wrong, developer can detect it easily, because they know what is the program doing now. But the con is that you are not sure is the operation finished correctly, if something wrong is inside the operation, for example, a function call gets blocked there and never return, you can't never know it by reading the logging records. With the after-style, you are sure the operation is done.

Of course, we can mix those two style together

Both:

log.info("Perform operation XXX")
operation()
log.info("Operation XXX is done.")

But I feel that is kinda verbose, it makes double logging records. So, here is my question - what is the good logging style? I would like to know how do you think.

Answer 1

I'd typically use two different log levels.

The first one I put on a "debug" level, and the second one on an "info" level. That way typical production machines would only log what's being done, but I can turn on the debug logging and see what it tries to do before it errors out.

Answer 2

It all depends what you want to log. If you're interested in the code getting to the point where it's about to do an operation. If you want to make sure the operation succeeded, do it after. If you want both, do both.