Code Quality - Logging

In complex projects, the time usually comes when it becomes indispensable for quality assurance to take further measures. I would like to discuss some of these aspects in a loose series:

In this article I’ll take a look at Logging.

Level

The simplest form of a log entry is a message. But it soon becomes clear that this alone will not be enough and a little more context is needed. Usually, the Timestamp and Level are added quickly. This can be implemented in this way, for example:

log.error()
log.warn()
log.info()
log.debug()

In environments like the browser these can be easily filtered, but in a log file it may look different. That is why I like to resort to a trick that I learned from my colleagues when working on a major project, namely to highlight these levels:

E|***
W|**
I|*
D|

Okay, that looks nice and clear, but what’s better?

It is the possibility to filter, because filtering to |* will show all messages including and above I|*, thus also warnings and errors. |** and |*** filter accordingly on higher levels. This works very well on macOS e. g. in Xcode or the Console App.

Time

A log entry usually starts with a time stamp. This makes sense for a program that runs in full productivity at the customer or on the server. During development, however, this information is rather superfluous and also shortens the visible area of the message. If time is of any interest at all, then it’s more like how much time has passed until this or that happens. Therefore, it may make sense to specify the time since the start of the program:

I|*       0ms App launch
D|      123ms Open file abc.xyz
E|***   412ms Could not open file abc.xyz because: Does not exist

Colors and Symbols

Another aspect that is helpful in the quick perception of information is the color of the entry. The browser does this for us by displaying the errors in red. But in some environments, such as Xcode, the use of colors is not possible or difficult to achieve, emojis can be used as an alternative:

🔷 I|*       0ms App launch
◽️ D|      123ms Open file abc.xyz
❌ E|***   412ms Could not open file abc.xyz because: Does not exist

The red symbol spotlights immediately and the error message is located so quickly.

Message Origin

Okay, we noticed there was an error, but where did it occur? The most amazing log entry is useless if we can’t locate the cause. For this reason, the file name and the line number should be logged as well. Many IDEs allow you to jump directly to a location through a specific formatting. In Xcode e. g. by CMD + SHIFT + O and then specify the file and the line number separated by a colon. This could look like this in the log:

🔷 I|*       0ms <main.c:33> App launch
◽️ D|      123ms <AppDelegate.m:54> Open file abc.xyz
❌ E|***   412ms <AppDelegate.m:62> Could not open file abc.xyz because: Does not exist

But! This is no information that should be used in a productive environment.

Concurrency

And yet another feature is important in modern programs, namely whether the message comes from an asynchronous code block or the main thread. A visualization with Emojis can be helpful here as well, like here with a rocket:

◽️ 🔷 I|*       0ms <main.c:33> App launch
🚀 ❌ E|***   412ms <MyCache.m:12> Expected files were missing

Conclusion

Even such an everyday topic as logging can still offer room for optimizations and thus save time in some places, because relevant information can be collected quickly and it is easier to locate the origin of the problem.

Published on January 25, 2018

 
Back to posts listing