Wilfred Thinking Aloud

Log, from Blammo!

In my continuing exploration of new ways to make my life easier, there used to be one thing that I couldn't solve in a satisyfing way. I know it sounds silly, but it's logging.

Now I can already hear you go like: "Why on earth would logging be a problem. There are APIs! In fact, there are plenty of them. There is Log4j, the de facto standard. There is JDK Logging, the de jure standard. And there is Commons Logging, if you can't choose between them. In fact, if you count in all of the proprietary logging API's, then - well then you would probably just loose count."

If that's the way you would respond, then I would nevertheless persist that logging can be ugly. There are a number of reasons:

Reasons to Have Another Logging Mechanism

• Configuration: I hate to start a project, and having to configure things first. I know, not all of the logging packages require you to have property files all of the time, but some of them do, and I can't stand it.
• Message Construction: there seems to be no way to do it right. If you use the + operator, then you will be accused of waisting your heap. If you want to be heap-savy, and use if (log.isDebugEnabled()) blocks, then half of your code exists of irrelevant if clauses. If you use the StringBuffer or the MessageFormat class, then you will be accused of obfuscating your code.
• Message Catalog: I like having a message catalog of everything that ever could be logged by my applications. If I use Logging API's directly, then it is impossible to construct such a message catalog, since message construction is happening somewhere in my code, and only humans are able to figure that out.
• Resource Bundle: I could use a resource bundle, and a MessageFormat class, but then I will never be sure that the messages defined in the Resource Bundle are expecting particular type number and order of Objects (or Object wrappers of primitives) in order to complete the message. Generally speaking, I hate the fact that I don't have compile time checking of these things. If I remove an Object from the array passed to the MessageFormat class, then I will not be aware of it until a RuntimeException is informing me about it.
• Testing: Testing if certain messages are logged is a disaster. First of all, it is a nightmare to get your hands on the logged messages from your JUnit TestCase. And then, you will need to parse the message to figure out if your message contains the appropriate information. Since the message could be changed in a resource file, your tests may be invalid in no-time. And you were not even interested in the actual message in the first place! You only cared about the specific parts.

Examples

Here are some logging examples. The first example is using JDK 1.4 features:

    public int div(int a, int b) {
        try {
            return a / b;
        } catch (ArithmeticException ae) {
            if (b == 0) {
                if (logger.isLoggable(Level.WARNING)) {
                    logger.warning("Attempt to divide " + a + " by " + b
                            + "; returning 0 instead.");
                }
                return 0;
            } else {
                if (logger.isLoggable(Level.SEVERE)) {
                    logger.log(Level.SEVERE, "Failed to divide " + a + " by "
                            + b + ".");
                }
                throw ae;
            }
        }
    }

Pretty ugly hu? And it's getting worse if I want to make it a little better; let's use a MessageFormat class instead:

	public int div(int a, int b) {
        try {
            return a / b;
        } catch (ArithmeticException ae) {
            if (b == 0) {
                if (logger.isLoggable(Level.WARNING)) {
                    String message = MessageFormat
                            .format(
                                    "Attempt to divide {0} by {1}; returning 0 instead.",
                                    new Object[] { new Integer(a),
                                            new Integer(b) });
                    logger.warning(message);
                }
                return 0;
            } else {
                if (logger.isLoggable(Level.SEVERE)) {
                    String message = MessageFormat.format(
                            "Failed to divide {0} by {1}.", new Object[] {
                                    new Integer(a), new Integer(b) });
                    logger.log(Level.SEVERE, message);
                }
                throw ae;
            }
        }

Testing the code above would be extremely complicated. These are just some examples to show why having something else, or something extra would make sense. In Blammo, my code would look like this:

    private Logger logger = (Logger) BlammoLoggerFactory.create(Logger.class);

    public int div(int a, int b) {
        try {
            return a / b;
        } catch (ArithmeticException ae) {
            if (b == 0) {
                logger.logDivisionByZero(a, b);
                return 0;
            } else {
                logger.logUnexpectedDivisionException(a, b, ae);
                throw ae;
            }
        }
    }

This code is much shorter and cleaner. But then again, in this case, I'm cheating. Instead of using a general purpose logging API, I'm using a Logger that is specific for my kind of events. But hold on, it's getting better: the only thing that I have to do to get this working is not to implement the interface, but simply to define the interface. Blammo will take care of the hard bits.

So the Java example above, actually had some more lines. It defines an inner interface declaration:

    /**
     * @blammo.logger
     */
    public interface Logger {

        /**
         * @blammo.level warning
         * @blammo.message Attempt to divide {a} by {b}; returning 0 instead.
         */
        void logDivisionByZero(int a, int b);

        /**
         * @blammo.level error
         * @blammo.message Failed to divide {a} by {b}.
         */
        void logUnexpectedDivisionException(int a, int b, ArithmeticException ae);

    }

Normally you would need to implement this interface manually, and then make sure that your private Logger reference gets populated with an instance of that implementation. This is where Blammo helps out. Blammo allows you to specify some JavaDoc based annotations, and generates everything for you. There are a couple of things to note here:

Observations

• In Blammo, the message refers to the parameters by name.
• In Blammo, you don't need to pass in Object[] arrays.
• Blammo will check if the parameter references actually resolve to parameters.
• At runtime, Blammo will use the MessageFormat class; the messages in the resource files generated by Blammo will contain '{0}' and '{1}', instead of '{a}' and '{b}'.
• Blammo is able to generate a fairly rich message catalog. The general idea is to use additional ordinary JavaDoc statements to provide details for the event.
• Blammo will use the second part of the operation name as the identifier of the message in the resource bundle. That means 'logDivisionByZero()' will create a property 'DivisionByZero'. This can be overridden by using the '@blammo.id annotation.
• Blammo does not have a specific way to write the messages to a particular file or a database, or whatever. Instead, it relies on lower-level logging APIs to take care of that bit. In that sense, Blammo is a little similar to Commons Logging. The main difference is: Commons Logging is providing yet another low-level API on top of existing other low-level APIs. Blammo instead provides a dedicated high-level logging API, on top of existing low-level APIs.
• Blammo works particularly well with dependency injection frameworks. Per default, your classes could use Null Loggers, and have property setters that allow it to be rewired to a real, environment specific Logger.
• Last but not least: Blammo is great (!) for testing. With the low-level API's it would be extremely hard to write a TestCase. With Blammo, it is actually pretty simple:

package com.agilejava.blammo.samples;

import org.easymock.MockControl;

import junit.framework.TestCase;

public class Sample2Test extends TestCase {

    MockControl loggerControl;

    Sample2.Logger logger;

    public void setUp() {
        loggerControl = MockControl.createControl(Sample2.Logger.class);
        logger = (Sample2.Logger) loggerControl.getMock();
    }

    public void testDivisionByZero() {
        Sample2 sample2 = new Sample2();
        sample2.setLogger(logger);
        int a = 3;
        int b = 0;
        logger.logDivisionByZero(a, b);
        loggerControl.replay();
        sample2.div(a, b);
        loggerControl.verify();
    }

    public void testDefaultDivisionByZero() {
        Sample2 sampl2 = new Sample2();
        int a = 3;
        int b = 0;
        sampl2.div(a, b);
    }

}

(And for insiders; yes, I do consider this the Stimpy way of logging. Have fun!)