Wilfred Thinking Aloud

Niks Relatief (Nothing Relative At All)

This summer, during the holidays, I read a great book on formal languages. It had been quite some time since I read something as fundamental as that, but after I got a taste of it, I find it hard to let go. So for this holiday, I added some semi-scientific literature to my wishlist.

The book that I ended up reading is called "Niks Relatief" - Dutch for "Nothing Relative At All" - by Vincent Icke. From the title, it might not be that obvious, but it is about relativity theory. Definitely interesting. It exists of two parts: the first part does not contain any formulas, and explains classical mechanics and quantum mechanics in general. The other part of the book explains the math behind all of it.

I never really enjoyed physics so much, partly because I almost electrocuted my sister when I was nine, thinking I had it all under control, and partly because it seemed to me that mathematicicans just had much more fun than physicists. This book makes me wonder if I should have given it a second chance, ten years ago.

Anyhow, it is a great book. The author does writes in a very compact way, and there are situations in which rookies like me loose track, but then again, this is entirely compensated by the enthousiasm and wit of the author.

Growing a Log

Tonight, I added a couple of more capabilities to the Blammo logging framework. Some of it has been done in order to provide some suppport for Sun's Unified Logging Format. The Unified Logging Format dictates that the message id is prefixing the actual message. Blammo already allowed you to specify the message id explicitly, but I wanted to have Blammo generate it for me, so I added that capability. Additionally, I added a mechanism to copy the JavaDoc comments for a certain event to the message catalog as an explanation.

That means that a message catalog could now potentially look like this:

The message ids have been generated, using the BLAM prefix and starting from message number 200. Both these properties are specified in the relevant section in your Maven pom:

      <plugin>
        <groupId>com.agilejava.blammo</groupId>
        <artifactId>blammo-maven-plugin</artifactId>
        <version>0.1-SNAPSHOT</version>
        <configuration>
          <messageIdPrefix>BLAM</messageIdPrefix>
          <messageIdOffset>200</messageIdOffset>
        </configuration>
      </plugin>

The additional comments for a certain message have been copied from the interface definition of the logger:

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

        /**
         * The application has attempted to divide something by zero, which is
         * impossible. This is a bug.
         * 
         * @blammo.level warn
         * @blammo.message Attempt to divide {a} by {b}; returning 0 instead.
         */
        void logDivisionByZero(int a, int b);

Agile vs. Monumental

A couple of days ago, I again experienced that traffic jams are just excellent opportunities for contemplation. While thinking about some recent experiences doing architecture work, my mind drifted off and I found myself trying comparing the different definitions of architecture of my customers. (I also found myself in need of the emergency break.)

All of a sudden, it dawned into me that these customers not only had different ideas on the approach for producing the architecture, but also different objectives. I'm sure everybody already figured that out, but quite honest, it was a nano-revelation for me.

I always figured that the objectives of the agile architect were similar to the objectives of the monumental architect, e.g. guarding systemic qualities like performance, scalability, security, etc. But I think I've come to believe that these are really 'afterthoughts' for the agile architect: we will fix it if it becomes a problem.

There is however one thing that can never be an afterthought in an agile project. The focus of an agile architect (aka coach) is predominantly on guarding a quality that is generally not listed as a systemic quality. The agile architect focuses on parallelization of the development process.

If working in parallel is not a requirement, then providing structuring principles is not necessary at all. However, if the size of the team increases beyond two, then there is a need to provide more structure, since people will need to work in parallel.

Blammo Report

A couple of days ago, I introduced the Blammo way of logging, stating that it would be easier to have a message catalog, for example to be included in your manuals. In reality, I didn't have an example of such a message catalog based on Blammo. Today, I'm happy to announce that I've been able to generate a first message catalog. It is not yet as complete as I want it to be, but I'm getting there.

Blammo Revisited

After yesterdays entry, I got two questions about the framework:

1. We want to use an ATG logger; how do we do that?
2. Is this convenient for debug logging?

Using other low level API's

Normally, if you need something else than the defaults, you are encouraged to inject this other implementation at runtime. You can however also set another default in your code that constructs the initial logger. Here is how you do it, assuming that you are working from the samples givin in my previous entry:

/*
 * Using a JDK Logger.
 */
Logger logger = (Logger) BlammoLoggerFactory
  .create(Logger.class, new BlammoJdkLog(java.util.logging.Logger.getLogger("Sample2")));

/*
 * Or the shorthand:
 */
logger = (Logger) BlammoLoggerFactory.create(Logger.class, new BlammoJdkLogFactory());

/*
 * Or do this:
 */ 
public voidSetBlammoLogFactory(BlammoLogFactory factory) {
  logger = (Logger) BlammoLoggerFactory.create(Logger.class, factory);
}

Mixing low-level and Blammo logging

Blammo is most definitely not the ultimate tool for low level debug logging. In fact, you shoul not even consider Blammo for this. That should not be a problem at all, since you can mix and match Blammo with other low level logging mechanisms that you like:

package com.agilejava.blammo.samples;

import java.util.logging.Logger;

import com.agilejava.blammo.BlammoJdkLog;
import com.agilejava.blammo.BlammoLoggerFactory;

public class Sample2 {

    private Logger logger = Logger.getLogger("Sample2");

    private EventLogger eventLogger = (EventLogger) BlammoLoggerFactory
            .create(EventLogger.class, new BlammoJdkLog(logger));

    public int div(int a, int b) {
        try {
            logger.fine("About to do something nasty.");
            return a / b;
        } catch (ArithmeticException ae) {
            if (b == 0) {
                eventLogger.logDivisionByZero(a, b);
                return 0;
            } else {
                eventLogger.logUnexpectedDivisionException(a, b, ae);
                throw ae;
            }
        }
    }

    /**
     * @param logger
     *            The logger to set.
     */
    public void setLogger(EventLogger logger) {
        this.eventLogger = logger;
    }

    /**
     * @return Returns the logger.
     */
    public EventLogger getLogger() {
        return eventLogger;
    }

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

        /**
         * @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);

    }

}

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!)