DaedTech

Stories about Software

By

Avoid these Things When Logging from Your Application

Editorial note: I originally wrote this post for the LogEntries blog.  You can check out the original here, at their site.  While you’re there, sign up for the service and check it out.

It seems almost strange to talk about avoiding things while logging.  After all, logging is your last line of defense or your salvation in many cases.  Some crazy bug in the field that shows up every third full moon?  An external auditor looking at your app’s runtime behavior?  Logging to the rescue.

So naturally, is stands to reason that you would want to log just about everything your application.  Whenever there’s any doubt, slam a logger call in there and let log level sort out the details.  You can always filter logs, but you can’t magic stuff into them after the fact.  So why, then, talk of avoidance?

wizard

Well, it turns out that, while logging may be a highly inclusive activity in terms of what should be included, there are ways to create problems.  You want to be liberal in terms of what you log, but judicious and wise in terms of how you log it.  You don’t want to indulge in a feckless free-for-all when it comes to the calls you make to your application’s logger.

So what are these problems, and how to avoid them?  Let’s take a look at some things that can come back to bite you.

Forgetting Context

If you want to avoid being hated by someone in the future, debugging with the log file, avoid forgetting context.  Did a message just arrive?  Perhaps instead of just saying, “message arrived” you should state what was in the message as well.  To see what I mean, consider this code.

public void ProcessFile()
{
    try
    {
        _fetcher.FetchFile();
    }
    catch(InvalidFileTypeException ifte)
    {
        _logger.Log("Invalid file type.")
    }
}

There’s a collaborator field called “fetcher” tasked with fetching a file.  The code anticipates that this action could result in the file type being invalid and, if that happens, it informs the user that the file type was invalid.

Really!?

You can’t go the extra mile and log the exception?  Or, absent that, at least inspect it to see what the offending file type is?

Try to put yourself in the position of the person reading this message and ask what they might be thinking.  “Oh, I see there was an invalid file type.”  It’s pretty much a certainty that they’re going to then ask, “what was this file type that proved invalid?”  Supply them with that context.

Cryptic Codes

Another source of log file woe related to lack of context (and, perhaps even a specific case of it), is having some sort of mystery code in a log entry.  Imagine perusing a log file and finding, “Error reading file: error 9024.”

The absolute best case scenario here is that I, as a maintenance programmer, have an encyclopedic knowledge of the application’s error codes.  Then, I’m in luck because I can say, “oh, that’s what happens when we process a file that uses the deprecated pipe-delimited format.”  But the next best scenario is a lot less rosy — I have to hunt down in the source code or in some documentation what that error code means.  And, worst of all would be this search dead ending at some magic number in the code.  At this point, the information in the log is basically useless.

If you’re going to log some code that’s fine, but also log along with it what it means, the way an exception is logged alongside an explanatory message.

Spamming the Log File

Have you ever seen a string of identical entries inside of a file that provided you with no valuable insight at all?  It is possible for your application to “spam” the log file, recording sequences of vacuous entries.  As a rather obvious example, consider a revamped version of the file fetcher from above.

public ConfigFile ProcessFile()
{
    while (_fetcher.GetStatus() != FileFetcherStates.Ready)
        _logger.Log("Waiting for filefetcher ready state.");

    var file = _fetcher.FetchFile();
    _logger.Log("File " + file.Name + " successfully fetched.");
    return file;
}

This could, quite possibly, result in tens of thousands of lines of “waiting for filefetcher ready state,” differing by only a timestamp.  Is that really a valuable use of your application’s logging?  At best, this provides you some statistics about the performance of the GetStatus() call, but there are other, less deluge-inducing options.  You could simply keep track of when you started polling, when you stopped, and how many times it happened, recording that information only.

As with context and codes, bear in mind what the log file will look like.  Logging in a tight loop is going to bury maintenance folks in quasi-useless information that would serve better in digest form.

Unsafe Logging Calls

Take a look at the code from the last example and see if you notice anything else that’s amiss.  Does something look fishy about that second call to the logger?

What happens if _fetcher.FetchFile() returns null?  Aside from the logger calls, the method would would return the null value.  But with that second logging call in the mix, the method will throw a null reference exception.  And that’s not good.

As a general rule of thumb, logging should be extremely safe as far as your application code goes.  After all, logging is important, but it tends not to be mission critical.  You don’t want it to affect actual runtime behavior; you want it to do its best to bear quiet witness to everything that happens.  So avoid invoking your logger in ways that can generate exceptions or cause other similar dependencies.

Mixing Application Logic with Logging

Had I not seen it for myself on various occasions, I might think that this one goes without saying.  But, apparently, it does not, so I’ll say it.  Avoid having your logging implementation do things that your application needs besides logging.

If you don’t understand what I mean, I’ve encountered situations where people have thought to wrap standard or home-grown logging implementations and couple them with other concerns, like other aspects or other types of file I/O.  In perhaps the most egregious example that I can recall, a home-rolled logging implementation became a handy repository for global variables, since it was universally acceptable and implemented as a static.  Needless to say, this created a hopelessly tangled mess in which the logger was actually critical to the application’s normal operation.

In general, it’s not good application architecture practice to couple things together unnecessarily, as the single responsibility principle advises.  But logging is an extremely unique application concern that behaves like nothing else, making it a particularly terrible candidate for this sort of thing.  Avoid having a logging implementation do anything but log.

Sensible Logging

As I mentioned in the beginning of the post, when it comes to logging, more is more.  You want to be capturing as much information about the state of your application as you can to arm maintenance programmers, operations folks, people reproducing errors, and really, any interested party.  To do that, you need to make sure you’re capturing the information, but you also need to make sure that you’re doing so in a sensible way.

8 Comments
Oldest
Newest Most Voted
Inline Feedbacks
View all comments
Thomas Lassanske
Thomas Lassanske
7 years ago

PC Load Letter

Erik Dietrich
7 years ago

Don’t smash the copier!

yoohoo
yoohoo
7 years ago

What is with you white, fat, balding programmers that causes you to regurgitate crap with mindless sarcasm and a supercilious attitude?

yoohoo
yoohoo
7 years ago
Reply to  yoohoo

I am very sorry about this comment. I regretted this as soon as I posted it. I have nothing against you personally. I was just angry at someone else and as always took it out on the Internet.

Erik Dietrich
7 years ago
Reply to  yoohoo

I’m a little confused, but… fair enough. If you want, I can’t delete the thread.

Thomas Lassanske
Thomas Lassanske
7 years ago
Reply to  yoohoo

What is it with these angry, anonymous programmers that causes them to spew bile at seemingly benign internet blog posts and then immediately regret it? 😉

Ian Yates
7 years ago

A very rare breed to post an apology immediately though. Actually made me smile. Doesn’t excuse the first post but I appreciate the follow-through.

Hugo
Hugo
7 years ago
Reply to  yoohoo

einfach wunderschön!