Example Logging Framework

Refactored from YagniAndLogging

How about anything that uses listeners or the ObserverPattern? These allow for functionality you do not know about a priori. In other words, the are anticipatory idioms. You have know idea whether you are going to need X, however you generalize in a way that allows X to be more easily added. From what I've read, this would be a classic violation of YouArentGonnaNeedIt. Does that mean that one shouldn't provide Observers in an XP environment?

To get more concrete, let's consider the Log Manager that was mentioned in the previous post. All you know initially is that you want to target log entries to the system output stream. You know there will be more targets down the road but do not know what they will be. Even worse, you are unsure what different types of entries may be handled by these imaginary targets. For trace logging, all you care about is a single string and that it be targeted to the System output stream. This is the only thing that is needed immediately.

My first instinct would be to violate YouArentGonnaNeedIt and DTSTTCPW by seting up something extensible and simple. First I might define a LogEntry interface. Instead of a complex log entry-type mechanism (like a singleton log entry-type server or enum classes), I may simply let the entry's subclass serve as its log entry-type. So, initially, I might only have the following:

 public
     interface LogEntry
     extends   java.util.EventObject
 {
     String toString();
 }

This gives me the future ability to filter entries based on class-type (if indeed I ever need to filter on entry-type). Additionally, I only ask concrete entries to define toString (instead of getString, getType, etc). This returns an output string that may or may not be made up of multiple attributes (such as type + timestamp + getMessage()). While I have seemingly violated YouArentGonnaNeedIt, I have also dealt with multiple entries in a somewhat generalized way and without dictating what attributes may be used by each entry type. I didn't spend time writing a complex enumeration class or integer server to have a customizable log entry type or category - but I did think about allowing for different types of entries in the <gasp> future.

Now that I've dealt with entries I need to deal with their targets (or handlers). Once again, because of my experience in different idioms, I can simply choose an extensible mechanism for doing this. Since I am working in the JavaLanguage, I decide to go with the listener idiom. To do this, I first need to define the LogEntry Listener Interface:

 public
     interface LogEntryListener
     extends   java.util.EventListener
 {
     void handle( LogEntry entry };
 }

Now, I need something to manage log entries and their listeners. I could make this an interface, but for expedience I just do something like the following:

 public class LogManager
 {
     private Items m_listeners = new ItemArray();

     public void addListener( LogEntryListener l ) {
         m_listeners.add( l );
     }

     public void removeListener( LogEntryListener l ) {
         m_listeners.remove( l );
     }

     public void enter( LogEntry e )
     {
         m_listeners.enum( new Block() {
             public void run( Object each ) {
                 ((LogEntryListener)each).handle( e );
     }
 }

Oddly, almost everything I have done so far anticipates future use and extension. From what I read about XP, I have already grossly violated DoTheSimplestThingThatCouldPossiblyWork and YouArentGonnaNeedIt. However, I have with little effort made my system much more resistent to change. Now will I write what I actually need for the moment -- a simple trace log entry, and a simple entry listener to write any kind of log string to System.out. First I write my log entry implementation for trace messages:

 public
     class   TraceLogEntry
     extends LogEntry
 {
     private String m_msg;

     public TraceLogEntry( String msg ) {
         m_msg = msg;
     }

     public String toString() {
         return m_msg;
     }
 }

Maybe next I go to my Debug interface and rewrite the trace method like so:

 static public void trace( String msg ) {
     LogManager.getInstance()
         .enter( new TraceLogEntry( msg ) );
 }

There are better ways to do this, but I already have the Debug.trace() calls throughout much of my existing code. Finally, I need to write a listener that outputs log-entries of any kind to System.out. But wait, because of the infrastructure I have put in place, I do not need to create anything more than an anonymous inner implementation of LogEntryListener. I might add something like the following to my initialization code:

 LogManager.getInstance()
     .addListener( new LogEntryListener() {
         public void handle( LogEntry e ) {
             System.out.println( e.toString() ); } } );

Now, when I say:

 Debug.trace( getClass() + ".fooBar - enter" );

The system will print the message to the system output stream. So, a couple of days go by and I realize that in addition to the immeadiate feedback I get from the output stream, I also want a persistent copy of the trace I can inspect later. Being the horrible violator of YouArentGonnaNeedIt that I am, I anticipate again by creating a resuable implementation of the listener interface that can work for System.out as well as it does for any other kind of PrintStream.

 public 
     class      StreamingLogEntryListener
     implements LogEntryListener
 {
     private PrintStream m_out;

     public StreamingLogEntryListener( PrintStream out ) {
         m_out = out; 
     }   

     public void handle( LogEntry e ) {
         m_out.println( e.toString() );
     }
 }

Now, I change my setup code from using the anonymous-inner listener to the following:

 LogManager lm = 
     LogManager.getInstance();

 lm.addListener( new StreamingLogEntryListener( System.out ) );
 lm.addListener( new StreamingLogEntryListener( <a-log-file> ) );

If I ever want to filter Trace entries out of a particular listener it becomes very simple. I could create a map in the Log Manager class that maps the Class object associated with a LogEntry class with one or more listeners and change the entry method to something like this:

 public void entry( LogEntry e )
 {
     Items listeners = m_map.at( e.getClass() );
     listeners.enum( new Block() {
         public void run( Object each ) {
             ((LogEntryListener)each).handle( e ); } } );
 }

Or, I could handle it in the actual listeners:

 class TraceEntryOnlyListener:
     public void handle( LogEntry e ) {
         if ( e instanceof TraceLogEntry )
             System.out.println( e.toString() );
     }

I could provide an abstract typed log entry listener that would generally allow listeners to OR various entry types together:

 class TypedLogEntryListener:
     public void handle( LogEntry e ) {
         if ( m_allowedTypes.has( e.getClass() ) )
             System.out.println( e.toString() );
     }

This allows me to create a listener scoped to various entry types. For example, say I have a listener that logs certain types of entries from over 100 workstations to a central location:

 l = getDistributedLogServerListener();

 l.add( NetworkEventLogEntry.class );
 l.add( SecurityLogEntry.class );
 l.add( ErrorLogEntry.class );

While I haven't added any of this filtering behavior, I have anticipated its implementation by the way I designed the LogEntry interface and the basic LogManager. In all honesty, I do not need the listeners either. I could simply update the enter method of LogManager class each time I need a new log entry handler/target. In fact, I don't even need the log entry interface. However, I chose to think generally and anticipatory. Now, I have an infrastructure in place that will allow me to have application logs, transaction logs, RMI server logs, AWT EventQueue logs, and so on just by the way I approached adding a trace log to my system. So, when I first created the LogManager, I had no idea I would eventually be sending log entries from many workstations to a single Jini service of JDBC Transaction Log. But because of my approach it is now easy to add. Should I feel guilty for my XP transgressions? Isn't this an example of InfrastructureCreep?

-- RobertDiFalco

When we did this, we spent money to get features we aren't using. How long would it take to put the logging in later? We'd have to touch a whole bunch of objects. Would it take an hour? A day? A week? A month? How much did our customer pay for code that isn't used and may never be?

YAGNI isn't about knowing or not knowing the future. It is about never doing anything today that can be safely put off until tomorrow. Logging looks like something that can be done easily, incrementally, and any old time. Why did we build it without using it?

---

Why not take a simple approach to begin with?

Write a LogManager class. Give it this method:

 public void log(String entry) {
   System.out.println(entry);
 }

The LogManager class gives you OAOO, whereas having multiple scattered System.out.println statements wouldn't, so this is fine.

Now, we get a requirement to handle multiple types of log entries. So we create the LogEntry interface mentioned above. We also create a StringLogEntryImpl class that contains a String and writes it back out again. Then we add the following method to the LogManager:

 public void log(LogEntry entry) {
   System.out.println(entry.toString());
 }

Then we refactor the log(String) method thusly:

 public void log(String entry) {
   log(new StringLogEntryImpl(entry);
 }

(You could also reuse a StringLogEntryImpl instance if you were worried about creating objects, but make the log method synchronized if you do.)

This simplistic approach does everything you need for now. Support for future LogEntry types is there. Extending the LogManager to do something more complex than a printout can be done in one place, perhaps by using the event-based system described above. Clients can use simple string-based logging until a need is found for more, then can use the more powerful future logging features when they're available, and as needed.

This seems to me to be a fairly DTTSTTCPW approach for the stated requirements. Programming to the LogEntry interface isn't a violation of XP; programming to interfaces is an accepted OO technique. As I could have written the classes in less time than it took to write this post, I don't think it's a huge time investment either.

Comments? -- RobertWatkins

But now you find that you need have log message types and severities such as INFO, WARN, and ERROR. Further more, the user wants these in a databse and be able to create reports based on the various message types. The LogEntry would still stand. The DTSTTCPW approach would require that many of those calls to #log change, since it could only take a string.