What makes a before/after vs. only before approach to logging more effective?

Question

I'm currently developing a server where I find myself asking whether something such as:

logger.info("Starting <action_1>.")
action_1()
logger.info("Ending <action_1>.")

logger.info("Starting <action_2>.")
action_2()
logger.info("Ending <action_2>.

vs.

logger.info("Starting <action_1>.")
action_1()

logger.info("Starting <action_2>.")
action_2()

would be a better practice of logging. I already recognize some arguments for both sides, specifically:

• By logging both at the start and end of an action, it'll be clear any logging done intermediately in the action itself is happening as part of the action. On the other hand, by only logging at the start of an action, any logging within the action could be confused for logging of a subsequent action.

• By logging only at the start of an action, you halve the efforts of updating what the action does later on. This is because you only need to update the action name / "spec" in one place, not two.

Is there any other arguments I should consider for one vs. the other?

Answer 1

By logging only at the start of an action, you halve the efforts of updating what the action does later on.

I just want to point out here that you really, really, really shouldn't consider typing effort to be the main contributor to software development time/effort.
By a massive margin, debugging and maintenance contribute significantly more to the development time/effort required to deliver a project according to its specifications.

Secondly, if you really hate having to adjust two log messages, then you must be fundamentally rewriting your code's purpose, which means you're violating OCP. That's going to lead to many issues. If you didn't violate OCP, you wouldn't need to rewrite the content of the log messages, at least not significantly.

Thirdly, here are ways around it, though they start adding complexity to the codebase:

public LogJob(string jobName, Action job)
{
    _log.Write($"{jobName}...");
    job();
    _log.Write($"Finished {jobname.ToLower()}...);
}

LogJob("Reticulating splines", () => ReticulateSplines() );
LogJob("Parsing prose",        () => ParseProse()        );

This is just a basic example, you'll need a generic variant when you're dealing with return types. The point I'm making is that you can automate the process that you're now complaining about, i.e. rewriting two log messages.

---

From the outset, I think we can agree that the answer is always going to be "how you should log depends on how you like your logs to be". But let's evaluate the consequences of the options you presented.

This is sort of the same argument as to whether you need to put {} on every if block. If you don't, then you are limiting yourself to the assumption that it should only describe one command, as it would be impossible to accurately infer how many commands would otherwise be part of the if.

Similarly, if you only log the start, then a log reader is unable to infer exactly what happened during that action, and what happened after it. They can only assume that the action ended when another started.

But what about submethods?

public void TestMethod()
{
    _log.Write("Reticulating splines...");
    ReticulateSplines();

    _log.Write("Parsing prose...");
    ParseProse();
}

public void ReticulateSplines()
{
    _log.Write("Divining essence...");
    DivineEssence();

    _log.Write("Morphing chakras...");
    MorphChakras();
}

This generate the following log:

Reticulating splines...
Divining essence...
Morphing chakras...
Parsing prose...

It seems an awful lot like those are 4 different steps, no? But in reality, there were only 3, the first action was further broken down into 2 steps, but you can't see that.

If your logging had been:

Reticulating splines...
Divining essence...
Finished divining essence...
Morphing chakras...
Finished morphing chakras...
Finished reticulating splines...
Parsing prose...
Finished parsing prose...

It would suddenly be a lot clearer exactly what happened.

A third option could be to add indentation to further highlight the hierarchy. This may not be relevant for your case but I have encountered cases where it did help an afwul lot to do something like:

Reticulating splines...
  Divining essence...
  Finished divining essence...
  Morphing chakras...
  Finished morphing chakras...
Finished reticulating splines...
Parsing prose...
Finished parsing prose...

---

But that doesn't mean you have to do so. There may be contextual considerations where knowing where each operation ends is irrelevant, or where it is abundantly clear without needing to be written down (e.g. because it describes an obviously sequential process).

I think your suggestion of only logging the start is born out of an assumption that the messages being logged are individual steps in a sequence. And when they are, then you can indeed infer that the start of the next line is the end of the previous one.

But if your logic (and thus logging thereof) goes any deeper than just a single sequence, your "start only" logging is going to be vague and render the logging ambiguous and less obvious to read without already knowing the internal logic.

What choice you make here is up to you. I don't know your business case or the business knowledge that your log readers will have.