Standardise logging in a enterprise product

Question

The software that I work upon has highly inconsistent logging. All logging is done in a single file and the file contains logging details from different modules and client interactions. The log file is highly cluttered and the least that I would like to do is to prepend some module information at the beginning of the line. For example as shown below I would like the logs have MODULE printed in the beginning.

#|2014-07-02T13:01:51.030+0530|INFO|glassfish3.1.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=104;_ThreadName=Thread-3;|3131149 [pool-23-thread-18] [rid=1112 session=f5fc97b0ac1802b000b94819c9518996 user=TTUser13] INFO **[MODULE1]**  com.xxxxx.Manager  - Client manager - getMo(Test) request received |#]

[#|2014-07-02T13:01:51.033+0530|INFO|glassfish3.1.1|javax.enterprise.system.std.com.sun.enterprise.server.logging|_ThreadID=104;_ThreadName=Thread-3;|3131153 [pool-23-thread-18] [rid=1112 session=f5fc97b0ac1802b000b94819c9518996 user=TTUser13] INFO **[MODULE2]** com.xxxxx.server.CliRmiService  - getMo(f5fc97b0ac1802b000b94819c9518996) - 3ms - com.xxxxx.ManagerObject@10f7afd

My suggestion to have individual logging across modules has met with lots of sceptical nods (not allowed). So the least I would like to do is to be able to add MODULE information at the beginning of each line. I use SPRING, JAVA and log4j (slf4j wrapper) in my software. Is there a easier way of doing this? I do not want to go to each logger statements and add that header. That would be highly inconvenient. Also, are there any other ways to deal with this problem?

Answer 1

The best way to deal with the problem is to refactor the code and introduce the logging you need. Sceptical nods just because people want to avoid touching legacy code are a smell, not an argument.

Now, answering your question: Even though AOP was not invented for patching up bad design or bad logging habits, you can use AspectJ for your purpose. "AOP lite" frameworks like Spring AOP are inappropriate here because Spring AOP only supports method execution interception, not method call interception, which is what you need here.

Here is a simple AspectJ sample. Please note that whenever I say "module", I mean the last part of the package name (after the last "."), e.g. module1 would be the module name if the package name is de.scrum_master.module1.

Two sample classes in different modules:

package de.scrum_master.module1;

import java.util.logging.Logger;

public class Person {
    private String firstName;
    private String lastName;

    public Person(String firstName, String lastName) { this.firstName = firstName; this.lastName = lastName; }
    @Override public String toString() { return "Person[" + firstName + " " + lastName + "]"; }
    public void doSomething() { Logger.getLogger("GLOBAL").info("Doing something with " + this); }
    public void doSomethingElse() { Logger.getLogger("GLOBAL").info("Doing something else with " + this); }
}

package de.scrum_master.module2;

import java.util.logging.Logger;

public class Place {
    private String country;
    private String city;

    public Place(String country, String city) { this.country = country; this.city = city; }
    @Override public String toString() { return "Place[" + city + ", " + country + "]"; }
    public void doSomething() { Logger.getLogger("GLOBAL").info("Doing something with " + this); }
    public void doSomethingElse() { Logger.getLogger("GLOBAL").info("Doing something else with " + this); }
}

Driver application using the modules:

package de.scrum_master.app;

import java.util.logging.Logger;

import de.scrum_master.module1.Person;
import de.scrum_master.module2.Place;

public class Application {
    private static final Logger LOG = Logger.getLogger("GLOBAL");

    public static void main(String[] args) {
        doPersonStuff();
        doPlaceStuff();
    }

    private static void doPersonStuff() {
        LOG.info("Start doing person stuff...");
        Person person = new Person("Albert", "Einstein");
        person.doSomething();
        person.doSomethingElse();
        person = new Person("Werner", "Heisenberg");
        person.doSomething();
        person.doSomethingElse();
        LOG.info("Finished doing person stuff");
    }

    private static void doPlaceStuff() {
        LOG.info("Start doing place stuff...");
        Place place = new Place("Indonesia", "Jakarta");
        place.doSomething();
        place.doSomethingElse();
        place = new Place("Germany", "Berlin");
        place.doSomething();
        place.doSomethingElse();
        LOG.info("Finished doing place stuff");
    }
}

Aspect:

The Aspect prepends an upper-case module name prefix like [MODULE1] to each log message. It would be quite straightforward to make the aspect log into different log files depending on class or package names instead. This is just a demonstration.

package de.scrum_master.aspect;

import java.util.logging.Logger;

public aspect LogModulePrepender {
    void around(String message) :
        call(public void Logger.*(String)) && args(message)
    {
        String packageName = thisJoinPoint.getSourceLocation().getWithinType().getPackage().getName();
        String moduleName = packageName.replaceFirst(".*[.]", "").toUpperCase();
        proceed("[" + moduleName + "] " + message);
    }
}

Log output:

Please note that for simplicity's sake I was using Java logging instead of Log4j when hacking together this little sample. It should be easy to adapt.

Jul 25, 2014 11:11:48 AM de.scrum_master.app.Application info_aroundBody0
Information: [APP] Start doing person stuff...
Jul 25, 2014 11:11:48 AM de.scrum_master.module1.Person info_aroundBody0
Information: [MODULE1] Doing something with Person[Albert Einstein]
Jul 25, 2014 11:11:48 AM de.scrum_master.module1.Person info_aroundBody2
Information: [MODULE1] Doing something else with Person[Albert Einstein]
Jul 25, 2014 11:11:48 AM de.scrum_master.module1.Person info_aroundBody0
Information: [MODULE1] Doing something with Person[Werner Heisenberg]
Jul 25, 2014 11:11:48 AM de.scrum_master.module1.Person info_aroundBody2
Information: [MODULE1] Doing something else with Person[Werner Heisenberg]
Jul 25, 2014 11:11:48 AM de.scrum_master.app.Application info_aroundBody2
Information: [APP] Finished doing person stuff
Jul 25, 2014 11:11:48 AM de.scrum_master.app.Application info_aroundBody4
Information: [APP] Start doing place stuff...
Jul 25, 2014 11:11:48 AM de.scrum_master.module2.Place info_aroundBody0
Information: [MODULE2] Doing something with Place[Jakarta, Indonesia]
Jul 25, 2014 11:11:48 AM de.scrum_master.module2.Place info_aroundBody2
Information: [MODULE2] Doing something else with Place[Jakarta, Indonesia]
Jul 25, 2014 11:11:48 AM de.scrum_master.module2.Place info_aroundBody0
Information: [MODULE2] Doing something with Place[Berlin, Germany]
Jul 25, 2014 11:11:48 AM de.scrum_master.module2.Place info_aroundBody2
Information: [MODULE2] Doing something else with Place[Berlin, Germany]
Jul 25, 2014 11:11:48 AM de.scrum_master.app.Application info_aroundBody6
Information: [APP] Finished doing place stuff