Counterintuitively, logging can lower readability
You've stumbled on a key issue here. Logging can inject orthogonal incentives for code readability.
When looking at code in general, the more terse a code snippet is (while still doing the same work), the more complex it is to read. So the incentive is to favor uncondensed code.
While you do want to introduce logging, if a large fraction of your code (text characters) pertains to logging, it starts distracting from the business logic (= non-logging code). In order to not distract from the business logic, the incentive becomes to favor condensed logging code.
But logging code is still code, and can be argued to be part of the business logic, e.g. when the requirements explicitly express the need for logging. So which is it, should we condense logging code or keep it uncondensed?
There is no one-size-fits-all answer here. You need to weigh your logging needs (specificity, verbosity, frequency, log levels, ...) against the impact it will have on the readability of your non-logging code.
Logging tips to minimize readability impact
Don't overdo the logging
You need to be sensitive to the amount of log messages you output. Too few and the logging becomes incomplete and debugging will be a guessing game, too much and the logs grow to massive proportions and debugging will be a jungle expedition, on top of the code also having to deal with this additional logging code. In either case, the benefit of having logs is being undercut and you should try to find the balance.
In your code example, you've overdone your logging, as there are two separate methods both logging that they are "starting step 1". That's twice the log messages you need.
I's arguable which one you should keep. I generally favor keeping the meta-information out of a method itself, and have each method only log its internal logic, not its own purpose. Something along the lines of:
reticulateSplines() {
Log.verbose("Flogging the plumbus");
// Plumbus flogging logic
Log.verbose("Porting the amons");
// Amon porting logic
}
main() {
Log.info("Started program");
Log.info("Reticulating splines");
step1();
Log.info("Finished reticulating splines");
Log.info("Program finished");
}
Avoid "finished X" messages where possible
These messages essentially also double the size of your log, and they usually don't really contribute much to the overall purpose of the log.
Generally speaking, when an error is logged and you're investigating it, you're only interested in the logging above the error. In my above example, if an exception was encountered during the "amon porting" logic, then your log should look something like:
Started program
Reticulating splines
Flogging the plumbus
Porting the amons
ERROR - NullReferenceException has been encountered
If every relevant job is prepended with a log message, then you know for a fact that when an error is logged, it occured during the job which was logged right before the error occurred, in this case "Porting the amons".
If there are nesting concerns here, where you want to be able to see that flogging the plumbus and porting the amons are subtasks of the larger spline reticulating logic, you could do that using the "finished XXX" messages to reveal the nested hierarchy. However, in order to cut down on the log size, it would be better if you used other methods of displaying the hierarchy, e.g. using indentation:
Started program
Reticulating splines
Flogging the plumbus
Porting the amons
ERROR - NullReferenceException has been encountered
Depending on your log style (flat file, xml/json file, database, ...), the way in which you reveal that hierarchy can change. But I generally suggest avoiding using "Finished XXX" messages when other ways of showing hierarchy are possible.
Doing so retains the hierarchical information without duplicating all the log messages. This will keep your code and your logs cleaner and more to the point.
Often, log messages denote method boundaries
Note that this only applies to log messages in the style of "Doing X".
When you feel like your logic needs to be logged using multiple "doing X" messages, such as flogging the plumbus and porting the amons, that generally implies that these two tasks are separate jobs, and therefore should be abstracted into methods of their own.
This means helps keeping your actual business code from being distracted by its logging. If your subtasks are abstracted into methods of their own, and the task itself merely consists of the orchestration of its subtasks and the logging of those tasks being done, then you're going to find that the logging isn't really obfuscating the business logic anymore since you've separated them.
reticulateSplines() {
Log.verbose("Flogging the plumbus");
flog(myPlumbus);
Log.verbose("Porting the amons");
port(amons);
}
flog(Plumbus myPlumbus) {
// Plumbus flogging logic
}
port(Amon[] amons) {
// Amon porting logic
}
Note that even if you personally favor putting the "Doing X" log method inside the X
method itself, which is a valid approach too, that still means your methods will only contain one of those messages, right at the top. The rest of the method body is then not being distracted by having additional log messages interspersed among its logic.
Understand who your reader is
Tailor your log messages to who will be reading them. If this log is intended to be read and interpreted by an end-user, you're going to need to explain a lot more in the log message than when your reader is a developer.
Try to minimize the log message length while keeping the message content clear to your reader.
Cut down on the fluff
Your code example already does this, but I wanted to explicitly point it out anyway, should you use a different approach/library for logging in the future.
By fluff, I mean the logging code that surrounds the log message itself. Using an example from C# and NLog, this is a bad way of doing things:
LogManager.GetCurrentClassLogger().Log("Reticulating splines", LogLevel.Info);
78 characters total, of which only 20 are the log message itself. That's a lot of fluff. It would be a lot better if we cut down on the fluff:
log.Info("Reticulating splines");
13 characters of fluff, 20 message characters. Much more readable. This of course means that you need to declare and instantiate your log
variable, but that can be done in another location, as far away from the business logic as possible, so it minimizes the distraction.
You might think that you could further cut down the size by replacing the message itself with an identifier, and then storing a dictionary of log messages which the logger makes use of. E.g.:
log.Info(538);
While that is technically possible, it's actually overkill to the point of negating your intention. Now, the code has become more complex, and it's not clear anymore which message is being logged. That means that you've just thrown out the documentative nature of your logging, where it can act as both a logging action and a sort of code comment at the same time.
Furthermore, most IDEs will color code strings, and over time you learn to look at the code while ignoring lines whose color coding shows that it's a string literal. For example:
When I look at this code, my mind instinctively skips over the string literals because it has been conditioned to do so with experience.
This is a variation on banner blindness where people learn to very quickly block out part of their perception when that part has historically been proven to not be interesting to them.
If you remove the string literals, you will generally lose out on the ability to mentally filter out those lines, since they look a lot more like your business code now:
step1()
,step2()
, etc...