Over a million developers have joined DZone.
{{announcement.body}}
{{announcement.title}}

A Better Way to Log For Safer, Tested Code

DZone's Guide to

A Better Way to Log For Safer, Tested Code

Zone Leader Sam Atkinson examines the gold standard for logging your code.

· DevOps Zone ·
Free Resource

Discover how quick and easy it is to secure secrets, so you can get back to doing what you love. Try Conjur, a free open source security service for developers.

All the code for this example can be found in GitHub.

One of the biggest smells for me coming onto a new code base is a proliferation of logging throughout the application. I’ve seen some classes where every other line of code may be logging. The usual excuse for this is “It’s just in case”, or “it helps us debug!”. That’s usually code for the fact the code hasn’t been written using TDD or tested in any real way. This is a recipe for disaster.

One of the other problems with this is that logging can be dangerous. Too many developers just assume that Log4J/SLF4J/Whatever new framework will *just work*. As any developer with an ounce of experience will tell you, if it can go wrong then it probably will.

This means that every 3-6 months there’ll be an issue, in UAT or production, caused by logging not behaving properly. I’ve seen low latency, business critical systems crippled by extra logging being spuriously added to help debug something. My favourite is the Heisenbug that is fixed by adding logging but reappears by taking it away. Lovely.

These are obviously symptomatic of a wider app problem with performance and application testing, and some bugs just refuse to reproduce themselves in test environments. But, in an ideal world, how should we log in our code? What’s the Gold standard?

Introducing ApplicationEvents

Logging is not something that should be done “just in case”. It should be with a specific, directed purpose. Usually, this is to indicate a life cycle event, such as the start or end of a triggered process. It could be to expose certain statistics if you haven’t built a proper tool for this yet. The key thing is that a log line should specifically derive from a requirement; some sort of need of your business or customer. If the line does not appear when it should then this should be a problem with red alarm bells.

As a requirement is a clear, testable unit. We should be able to test our logging. Does the application log at the correct times? Does it log the correct line? This should all be easily testable.

In reality testing logging code isn’t that simple. Most logging frameworks have some kind of static initialisation (Yay! Global State!) which makes it hard to test; you can hack around by reading the output log file, but that’s not particularly clean or quick. Instead, we can use an ApplicationEvents class.

The ApplicationEvents interface has a method for each important event in your application that needs to be logged; think methods like beginStartOfDay() or databaseConnected(). I’ve worked on large enterprise applications which have had less than 30 different methods, but it’s perfectly feasible to break the class up to multiple ApplicationEvents if it becomes unweildy. This is then passed into the classes that need it (AKA dependency injection). This means it can be mocked for tests easily and different implementations created for interesting purposes.

A Concrete Example

public static void main(String[] args) {
        StartOfDayListener startOfDayListeners = new CompositeStartOfDayListener(
                new SomeStartOfDayProcess(),
                new SomeStartOfDayProcess(),
                new SomeStartOfDayProcess()
        );

        get("/beginStartOfDay", new SoDHandler(startOfDayListeners));
    }


    private static class SoDHandler implements Route {
        public static Logger LOGGER = LoggerFactory.getLogger(SoDHandler.class);

        private StartOfDayListener startOfDayListeners;

        private SoDHandler(StartOfDayListener startOfDayListeners) {
            this.startOfDayListeners = startOfDayListeners;
        }

        public Object handle(Request request, Response response) throws Exception {
            LOGGER.info("SOD Requested, handling...");
            startOfDayListeners.onStartOfDay();
            LOGGER.info("SOD Finished");
            return "Start of Day complete";
        }
    }

In this example we have a very basic web server which accepts one request, to begin the Start of Day (SOD) process. When called, onStartOfDay() will be called on the anything subscribed to the event notification.

We have 2 pertinent log lines; one to say SOD has been requested, and one to say it has finished. Currently it’s very difficult to test these lines; normally we would ignore them and confirm functionality by checking the onStartOfDay method is called. But these are the sort of loglines which are often critical in monitoring, and even in this contrived example they are important enough to be tested.

The easiest way to test this is to replace the log lines with an ApplicationEventsLogger (an interface I have created).

 private static class SoDHandler implements Route {
        public static Logger LOGGER = LoggerFactory.getLogger(SoDHandler.class);

        private StartOfDayListener startOfDayListeners;
        private ApplicationEvents applicationEvents;

        private SoDHandler(StartOfDayListener startOfDayListeners, ApplicationEvents applicationEvents) {
            this.startOfDayListeners = startOfDayListeners;
            this.applicationEvents = applicationEvents;
        }

        public Object handle(Request request, Response response) throws Exception {
            applicationEvents.onStartOfDay();

            startOfDayListeners.onStartOfDay();

            applicationEvents.startOfDayEnds();

            return "Start of Day complete";
        }

    }

public interface ApplicationEvents extends StartOfDayListener {
    void onStartOfDay();
    void startOfDayEnds();
}

We can now create a mocked version of ApplicationEvents and assert that the start and end log lines are called. One of the reasons TDD is great is because it forces you to think about the design.  Should the end log line be called if there is an exception in the listeners? That’s something that is now directly specified in the tests.

ApplicationEvents should exist once per application.  Add new methods to the interface as you require them.  This should conciously force you to think "do I need to this log line?". This will hopefully prevent spurious logging.

A Little Further

You’ll notice the duplicated method name for onStartOfDay in ApplicationEventsLogger and StartOfDayListener. We can now go a step further and make our ApplicationEvents extend StartOfDayListener and include this as a listener at the start. The logging doesn’t then clutter the code base as much.  If you're using the listener pattern extensively in your codebase you should find that logging then becomes a lot more transparent, and your code base is much cleaner and easier to handle.

static ApplicationEvents applicationEvents = new ApplicationEventsLogger();

    public static void main(String[] args) {
        StartOfDayListener startOfDayListeners = new CompositeStartOfDayListener(
                applicationEvents,
                new SomeStartOfDayProcess(),
                new SomeStartOfDayProcess(),
                new SomeStartOfDayProcess()
        );

        get("/beginStartOfDay", new SoDHandler(startOfDayListeners, applicationEvents));
    }

In Conclusion

I’m always frustrated writing posts like this that I can’t post to a large codebase using the patterns under discussion, as simple examples often don’t show the power in the pattern under discussion. If you’re starting a new project I highly recommend trying to extract your logging into a dedicated class like this and seeing how much it can improve your code base stability, as well as the cleanliness of your code.

Conjur is a free open source security service built by DevOps engineers. With integrations with all your favorite tools and an easy way to secure secrets, it's a no brainer. Come check it out!

Topics:
java ,logging ,patterns

Opinions expressed by DZone contributors are their own.

{{ parent.title || parent.header.title}}

{{ parent.tldr }}

{{ parent.urlSource.name }}