Evan Summers's Blog

Gooey Logger

Spoiler Warning! The following pitch is a spoiler for the actual um, article...

Stairwell Pitch

Logging is a fundamental tool of software development. But using System.out.println() is for monitoring is um, not very convenient. So we rather implement a logger which can accept variable arguments, infer the class and method by default, and format our objects nicely for us.

Demos

You can see this type of logger in service in the CookieJar, its Address Form demo, and other true stories.

Implementation

I like the Java Logging API. So we implement a logger in the spirit of java.util.logging.Logger.

public class QLogger {
    protected static QLoggerProperties properties = new QLoggerProperties();
    protected static QLoggerFormatter formatter = new QLoggerFormatter();
    ...
    protected String loggerName;
    protected Level level;

    protected Logger delegateFileLogger;

    public QLogger(String loggerName) {
        this.loggerName = loggerName;
        String levelKey = loggerName + ".level";
        String levelValue = System.getProperty(levelKey, "INFO");
        setLevel(Level.parse(levelValue));
        ...
    }

    public void entering(Object ... args) {
        logp(Level.FINER, "entering:" + formatter.formatArgs(args));
    }
    ...
}

We get the desired verbosity level for this logger from the command-line system properties, eg. -Dlogger.level=FINEST.

We implement the following method to log if the message has a sufficient level.

    public void logp(Level level, String string) {
        if (!isLoggable(level)) return;
        StackTraceElement frame = getStackFrame();
        String className = getSimpleClassName(frame.getClassName());
        QLogRecord record = new QLogRecord(level, string);
        record.setSourceClassName(className);
        record.setSourceMethodName(frame.getMethodName());
        record.setLoggerName(loggerName);
        record.setLineNumber(frame.getLineNumber());
        if (delegateFileLogger != null) delegateFileLogger.log(record);
        log(record);
    }

where by default we get the stack frame, if it's loggable, and pay the performance price. Hopefully we can afford it.

Comments

• 
  FINER:logger:BCommon:loadResourceBytes:270:entering:(String)splash1.html
  FINER:logger:BCommon:loadResourceBytes:275:exiting:(String)/webroot/splash1.html:(Integer)1050
  FINER:logger:CookieJarLoader:actionPerformed:293:entering:(String)Next
  FINER:logger:BCommon:loadResourceBytes:270:entering:(String)splash2.html
  FINER:logger:BCommon:loadResourceBytes:275:exiting:(String)/webroot/splash2.html:(Integer)2063
  FINER:logger:CookieJarLoader:startServer:222:entering:(Boolean)false
  FINER:logger:BCommon:loadJar200UrlBytes:306:entering:(String)http://jroller.com/resources/e/evanx/aptcomponent.jar.unsigned.pack.gz.jar
  SEVERE:logger:BCommon:handleException:358:BindException:Address already in use: JVM_Bind:(String)
  SEVERE:logger:BCommon:handleException:358:[Ljava.lang.Object;@1e3a0ec
  java.net.BindException: Address already in use: JVM_Bind
  at java.net.PlainSocketImpl.socketBind(Native Method)
  at java.net.PlainSocketImpl.bind(Unknown Source)
  at java.net.ServerSocket.bind(Unknown Source)
  at java.net.ServerSocket.(Unknown Source)
  at java.net.ServerSocket.(Unknown Source)
  at webservlet.BServer.run(BServer.java:39)
  :
  INFO:logger:BCommon:loadJar200UrlBytes:315::(String)http://jroller.com/resources/e/evanx/aptcomponent.jar.unsigned.pack.gz.jar:(Integer)-1
  INFO:logger:BServer:putResource:166::(String)/aptcomponent.jar:(Integer)598394
  FINER:logger:CookieJarLoader:actionPerformed:293:entering:(String)Back
  FINER:logger:BCommon:loadResourceBytes:270:entering:(String)splash1.html
  FINER:logger:BCommon:loadResourceBytes:275:exiting:(String)/webroot/splash1.html:(Integer)1050
  FINER:logger:CookieJarLoader:actionPerformed:293:entering:(String)Next
  FINER:logger:BCommon:loadResourceBytes:270:entering:(String)splash2.html
  FINER:logger:BCommon:loadResourceBytes:275:exiting:(String)/webroot/splash2.html:(Integer)2063
  FINER:logger:CookieJarLoader:startServer:222:entering:(Boolean)false
  SEVERE:logger:BCommon:handleException:358:IllegalThreadStateException:null:(String)
  SEVERE:logger:BCommon:handleException:358:[Ljava.lang.Object;@b52a28
  java.lang.IllegalThreadStateException
  at java.lang.Thread.start(Unknown Source)
  at webservlet.BServer.startServer(BServer.java:161)
  at cookiejar.CookieJarLoader.startServer(CookieJarLoader.java:226)
  at cookiejar.CookieJarLoader.actionPerformed(CookieJarLoader.java:309)
  at javax.swing.AbstractButton.fireActionPerformed(Unknown Source)
  at javax.swing.AbstractButton$Handler.actionPerformed(Unknown Source)
  at javax.swing.DefaultButtonModel.fireActionPerformed(Unknown Source)
  at javax.swing.DefaultButtonModel.setPressed(Unknown Source)
  at javax.swing.plaf.basic.BasicButtonListener.mouseReleased(Unknown Source)
  at java.awt.Component.processMouseEvent(Unknown Source)
  at javax.swing.JComponent.processMouseEvent(Unknown Source)
  at java.awt.Component.processEvent(Unknown Source)
  at java.awt.Container.processEvent(Unknown Source)
  at java.awt.Component.dispatchEventImpl(Unknown Source)
  at java.awt.Container.dispatchEventImpl(Unknown Source)
  at java.awt.Component.dispatchEvent(Unknown Source)
  at java.awt.LightweightDispatcher.retargetMouseEvent(Unknown Source)
  at java.awt.LightweightDispatcher.processMouseEvent(Unknown Source)
  at java.awt.LightweightDispatcher.dispatchEvent(Unknown Source)
  at java.awt.Container.dispatchEventImpl(Unknown Source)
  at java.awt.Window.dispatchEventImpl(Unknown Source)
  at java.awt.Component.dispatchEvent(Unknown Source)
  at java.awt.EventQueue.dispatchEvent(Unknown Source)
  at java.awt.EventDispatchThread.pumpOneEventForHierarchy(Unknown Source)
  at java.awt.EventDispatchThread.pumpEventsForHierarchy(Unknown Source)
  at java.awt.EventDispatchThread.pumpEvents(Unknown Source)
  at java.awt.EventDispatchThread.pumpEvents(Unknown Source)
  at java.awt.EventDispatchThread.run(Unknown Source)
  :
  

  Posted by: coxcu on November 20, 2006 at 07:39 AM

• The relevant line there is

  java.net.BindException: Address already in use: JVM_Bind

  which means um, the address is already in use ;) That would be port 8005 on your localhost. This can happen if you run the demo twice?

  Posted by: evanx on November 20, 2006 at 10:27 AM

• Hi Evan,

  Just wondering if there is a reason you wrote your own logger rather than using one of the existing ones?

  JDK Logging
  Log4J
  Simple Log

  PS - Getting a stack frame every time you want to log one message is likely to be very expensive. Those libraries that provide that functionality usually recommend against using it.
  Cheers,
  Graham.

  Posted by: grlea on November 21, 2006 at 03:13 AM

• As a favour to anyone else who posts a comment...

  ... the text should no longer be bold.

  Posted by: grlea on November 21, 2006 at 03:14 AM

• (Oh well, it was worth a try.)

  Posted by: grlea on November 21, 2006 at 03:14 AM

• 
  Hiya Graham! Thanks for the comment. I will check out simple log - thanks for that.

  To answer your question, I originally did it cos i wanted to use JDK Logging, but

  (1) i didn't want to specify the class name and method name, but rather infer these by default (which is argubly fine in development, for event driven swing apps, if not production of server side apps)

  (2) i wanted java5 varargs, with convenient formatting, to make it easy to chuck in logging. For example, logger.entering(component) where component might be null, but if not, we want to see the simple class name and name of this component, and not toString().

  (3) writing a Logger wrapper helped me learn JDK Logging ;)

  At the time i had to choose between Log4J and JDK logging. I preferred JDK logging cos it was more "code" and OO, whereas Log4J was more declarative XML

  On the stack frame performance issue, certainly this should be a feature you can switch on and off. In development of Swing apps (which are sitting idle in the EDT 95% of the time), i don't think this is a big issue. In production, verbosity would be at INFO level anyway, and but of course you might wish to change the default and require -Dlogger.stackFrame=true.

  Posted by: evanx on November 21, 2006 at 03:43 AM

• "which means um, the address is already in use ;) That would be port 8005 on your localhost."

  It seems that a default install of Tomcat uses port 8005 to listen for shutdown requests. The general lesson is that you can't assume any given port will be free.

  Posted by: coxcu on November 21, 2006 at 10:48 AM

• 
  SEVERE:logger:BCommon:handleException:358:IOException:Server returned HTTP response code: 503 for URL: http://jroller.com/resources/e/evanx/aptcomponent.jar.unsigned.pack.gz.jar:(String)
  SEVERE:logger:BCommon:handleException:358:[Ljava.lang.Object;@dfe491
  java.io.IOException: Server returned HTTP response code: 503 for URL: http://jroller.com/resources/e/evanx/aptcomponent.jar.unsigned.pack.gz.jar
  at sun.net.www.protocol.http.HttpURLConnection.getInputStream(Unknown Source)
  at cookiejargui.BCommon.loadJar200UrlBytes(BCommon.java:312)
  at cookiejar.CookieJarLoader$3.run(CookieJarLoader.java:240)
  at java.lang.Thread.run(Unknown Source)
  

  Posted by: coxcu on November 21, 2006 at 10:52 AM

• 
  coxcu, thanks for that info. Another reader had this problem - at least now i know the problem (thanks)! so 8005 is a bad choice of port - i will choose another one - any suggestions?

  Maybe i'll try a port number eg. 8091 and if get an exception, increment the port number, a few times?

  On the issue of URLConnection error, i don't retry if there is an exception there. Anyway, the other demos should work. And mostly importantly for this article on logging, the logging seems to be working ;) Exception for that second line there showing java.lang.Object instead of toString() but i fixed that yesterday. Problem is that i've been reorganising the code and demos, splitting it out of aptfoundation into own projects eg. quitebusy, quiteditty, quitegooey, and also cookiejar stuff into cookiejar and out of webservlet, and now i need to make cookiejar support 5 builtin jars and 2 external jars, instead of the current 1 builtin and 1 external - so i will be working on that through this weekend...

  
  

  Posted by: evanx on November 21, 2006 at 11:05 AM

• I suggest trying 10 ports at random and using the first one that is free. On success, make the port number obvious.

  Posted by: coxcu on November 21, 2006 at 03:16 PM

• After spending a few hours updating and upgrading CookieJar, i decided to "deprecate" it, cos Java6's good security means you have to edit the jre/security/javaws.policy file for the CookieJar JNLP to work. I dunno if its worth keeping the .jar file going because i hear that WinZip et al steal that .jar MIME association? i use 7zip and i'm fine, but maybe i'm the only one ;)

  Posted by: evanx on November 21, 2006 at 03:33 PM

This work is licensed under a Creative Commons License.