Reconfiguring Log4j at runtime

At the start of my latest project I realized that I often take for granted the presence of log4j. For me it's just a given that it will be in my next app and that everyone already knows how to hack log4j for their own needs. Not so!

While including Log4j in your app and calling debug is usually a given I think I'm one of a hand full of people that have actually looked over the JavaDocs to discover what else lgo4j can do for me. Hey it's OK, we all have deadlines and reading logger JavaDocs isn't exactly on the critical path right?

If you haven't yet, I would encourage you to skim through the JavaDocs. For those who decline or are just too busy, I'd like to share a nice feature that will save you some serious time.

So, how would you like to control the log4j Loggers in your application deployed to production or anywhere off of you local environment?  More often then not you just don't get the option to leave debugging on in production since SysAdmins don't care much for verbose logging on their servers and rightly so since logs can grow rapidly if your a good user of debugging. What you really need is a logger admin page in your app where you can change the logging levels of configured loggers and add new, something like the following image.

(Note:Some package names were obscured to protect the innocent)

In the above image you see a logger manager screen where you can change the logging level as well as a text box where you could enter a new Logger such as com.mycorp.myapp.dao or the full path of a specific class.

So how's all this work? It pretty much comes down to Log4j Loggers and their Levels. First off is the Logger which in the case of Log4j can only be created by calling a static Factory method, Logger.getLogger(String name). If you have used Log4j before you are no doubt well acquainted with this method when your creating a logger for a specific Class. All instances of Logger are children of the RootLogger which always exists in log4j and can only be retrieved by calling Logger.getRootLogger(). This is how log4j can perform its logging at the class or package level and only print out messages at the root configured level such as ERROR which tends to be the default level.

Speaking of Levels, all loggers are configured to log at a  specific Level which is inherited from the parent logger such as the RootLogger or another logger in the family tree specified by package notation in the name. For example com.foo is a parent to com.foo.bar, If the root is configured at ERROR com.foo.bar would be at ERROR as well unless com, com.foo, or com.foo.bar have Loggers are configured at a different Level.
 Looking at the above screen shot you should be able recognize the Loggers and their assigned Levels.

Now let me explain that form displayed above. At the top of the form is the Logger Name text box which allows you to create a new Logger. Lets say you want to create a logger for com.foo.bar.model.dao.MyDAO; you simply type that or some part of that package into the text box, select a level like DEBUG and click OK. The form updates itself and the new logger is displayed on the form. Logging for that level will be activated and you'll be able to see whats going on!

After your done debugging whats wrong with MyDAO you might want to set its Logging Level back to ERROR, to do this simply change the Level in the drop-down and the form submits updating the Logger to its new Level. Easy real time management of Logger Levels!

So  enough theory and rambling, your here her for the code, I know you are! Let me walk you through the code now! Most of the example code is your general MVC stuff so I'll point out the overall structure and then point out the interesting parts in each class file.  I am currently working with JSF for my views so this example has JSF in the view but should translate to a jsp very simply if desired. 

LoggerManager which acts as the Controller of creating Loggers and LoggerAdmin a Form BackingBean which takes care of the view logic. In addition there are two supporting files, ComparableLogger and of course the html view.

The LoggerManager acts as our service/controller layer which contains 2 aptly named methods, getLoggers() and addLogger(). The getter provides a controlled manner for the front end to retrieve the current log4j Loggers as a list of ComparableLoggers which extend the log4j Logger class (keep reading for details on  ComparableLogger).


Enumeration<logger> loggers = LogManager.getCurrentLoggers();
while (loggers.hasMoreElements())
{
    Logger lgr = loggers.nextElement();
    if(lgr != null &amp;&amp; filterUnconfigured)
    {
        if(lgr.getLevel() != null)
            list.add(new ComparableLogger(lgr));
        }
        else
        {
            list.add(new ComparableLogger(lgr));
        }
    }
Collections.sort(list);


The code here is requesting the list of Loggers by making a call to the static LogManager.getCurrentLoggers(). This returns an Enumeration which includes items that have no Log level there by taking the default. Those set to default can be ignored, so we loop through the returned Loggers building a List of Loggers with a logging level and in the process converting them to ComparableLoggers for later sorting.

Wow that you know how to get the active Loggers, you'll want to be able to add new ones! You have most likely done this before, simply pass the new Name of the logger, something like "com.foo.dao" and also include a logging Level in the form of an int constant defined in the Level class. Then create a new logger as you normally would.


...
Logger newLog = Logger.getLogger(newLoggerName);
Level newLevel = Level.toLevel(newLogLevel);
newLog.setLevel(newLevel);
...


Well that is the meat of the code right there, pretty simple really! The rest of the code is, as I mentioned, display oriented code. I'll run though the other classes and their purpose real quick to help you with the full picture.  The next class, LoggerAdmin, is referred to as a a Backing bean because it is a jova object representation of the view. Its responsibilities include containing data and managing view logic. You'll notice that it does some translating to provide logger levels for the UI as well as passing long the UI requests to the Service layer.

The next object is ComparableLogger and as mentioned before it exists to provide a sortable wrapper for a Logger object. Finally there is the manageLogger.xhtml file used by the Faces framework to generate the view. Faces is far outside the scope of this posting but looking it over should give you a general idea of what your view ought to be doing.

I have included all of the code below:

LoggerManager.java
package org.lee.twobytes.managelogger;

import java.util.ArrayList;
import java.util.Collections;
import java.util.Enumeration;
import java.util.List;

import org.apache.log4j.Level;
import org.apache.log4j.LogManager;
import org.apache.log4j.Logger;

/**
 * Provides access helpers for retrieving Logger information about the running
 * application.
 *
 * @author lclarke
 */
public class LoggerManager
{
    /**
     * Lists only configured loggers in Log4j also sorts the results by name.
     *
     * @return
     */
    public List getActiveLoggers()
    {
        return getLoggers(true);
    }

    /**
     * Lists ALL active loggers in Log4j also sorts the results.
     *
     * @return
     */
    public List getAllActiveLoggers()
    {
        return getLoggers(false);
    }

    protected List<comparablelogger> getLoggers(boolean filterUnconfigured)
    {
        // Logger rootLogger = Logger.getRootLogger();
        ArrayList list = new ArrayList();

        Enumeration loggers = LogManager.getCurrentLoggers();
        while (loggers.hasMoreElements())
        {
            Logger lgr = loggers.nextElement();
            if (lgr != null && filterUnconfigured)
            {
                if (lgr.getLevel() != null)

                    list.add(new ComparableLogger(lgr));
            }
            else
            {
                list.add(new ComparableLogger(lgr));
            }
        }
        Collections.sort(list);
        return list;
    }

    /**
     * Creates the new Logger
     *
     * @param newLoggerName
     * @param newLogLevel
     * @throws TINException
     */
    public void addLogger(String newLoggerName, Integer newLogLevel)

             throws Exception
    {
        if (newLoggerName != null && newLogLevel != null)
        {
            Logger newLog = Logger.getLogger(newLoggerName);
            Level newLevel = Level.toLevel(newLogLevel);
            newLog.setLevel(newLevel);
        }
        else
        {
            throw new Exception("Logger information was invalid or null.");
        }
    }
}


LoggerAdmin.java

package org.lee.twobytes.backingbeans.admin;

import java.util.ArrayList;
import java.util.Collections;
import java.util.List;

import org.apache.log4j.Level;
import org.apache.log4j.Logger;

import org.lee.twobytes.model.NameValuePair;
import org.lee.twobytes.model.ComparableLogger;
import org.lee.twobytes.model.LoggerManager;
import org.lee.twobytes.model.exceptions.TBException;

/**
 * Provides access to Logger manager for the display and configuration of log4j
 * loggers.
 *
 * @author lclarke
 */
public class LoggerAdmin extends AdminBaseBean
{

    private static final Logger logger = Logger.getLogger(LoggerAdmin.class);

    private static List<NameValuePair<String, Integer>> LogLevels2;
    static
    {
        LogLevels2 = new ArrayList<NameValuePair<String, Integer>>();
        LogLevels2.add(new NameValuePair<String, Integer>
            (Level.WARN.toString(), Level.WARN.toInt()));
        LogLevels2.add(new NameValuePair<String, Integer>
            (Level.TRACE.toString(), Level.TRACE.toInt()));
        LogLevels2.add(new NameValuePair<String, Integer>
            (Level.DEBUG.toString(), Level.DEBUG.toInt()));
        LogLevels2.add(new NameValuePair<String, Integer>
            (Level.ERROR.toString(), Level.ERROR.toInt()));
        LogLevels2.add(new NameValuePair<String, Integer>
            (Level.FATAL.toString(), Level.FATAL.toInt()));
        LogLevels2.add(new NameValuePair<String, Integer>
            (Level.INFO.toString(), Level.INFO.toInt()));
        LogLevels2.add(new NameValuePair<String, Integer>
            (Level.OFF.toString(), Level.OFF.toInt()));
      
        Collections.sort(LogLevels2);
    }

    private LoggerManager loggerManager;
    private String currentLoggerName = null;
    private String newLoggerName = null;
    private Integer newLogLevel = Level.DEBUG.toInt();
  
    public String getCurrentLoggerName()
    {
        return currentLoggerName;
    }

    public void setCurrentLoggerName(String currentLoggerName)
    {
        this.currentLoggerName = currentLoggerName;
    }

    public List<ComparableLogger> getActiveLoggers()
    {
        return loggerManager.getActiveLoggers();
    }

    /**
     * Adds a new logger to the app for the specified classpath
     */
    public String processAdd()
    {
        logger.debug("ADD LOGGER: name:" + this.newLoggerName + " Level:" + this.newLogLevel);
        try
        {
            loggerManager.addLogger(this.newLoggerName,  this.newLogLevel);
            this.setInfoMessageByKey("label.settingsSaveSuccess", null);
            this.newLogLevel = Level.DEBUG.toInt();
            this.newLoggerName = null;
        }
        catch (TBException e)
        {
            this.setInfoMessageByKey("label.erroraddinglogger", null);
        }
      
        // this.notesHandler.notifyReload();
        // } catch (TBException e) {
        // this.handleSystemError("error updating config items", e);
        // }  
        return null;
    }

    /**
     * Updates the logger that changed levels.
     * @return
     */
    public String processUpdate()
    {
        if (this.currentLoggerName != null)
        {
            logger.debug("Updating logger: "+this.currentLoggerName);
        }
        return null;
    }

    /**
     * Drives display values for the dropdown
     *
     * @return
     */
    public List<NameValuePair<String, Integer>> getLogLevels()
    {
        return LogLevels2;
    }

    public LoggerManager getLoggerManager()
    {
        return loggerManager;
    }

    public void setLoggerManager(LoggerManager loggerManager)
    {
        this.loggerManager = loggerManager;
    }

    public String getNewLoggerName()
    {
        return newLoggerName;
    }

    public void setNewLoggerName(String newLoggerName)
    {
        this.newLoggerName = newLoggerName;
    }

    public Integer getNewLogLevel()
    {
        return newLogLevel;
    }

    public void setNewLogLevel(Integer newLogLevel)
    {
        this.newLogLevel = newLogLevel;
    }
}



ComparableLogger.java
package org.lee.twobytes.managelogger.model.ComparableLogger;

import org.apache.log4j.*;

/**
 * I wanted to sort Loggers but, they aren't comparable... this takes care of
 * that. IT sorts on the Logger name by default.
 *
 */
public class ComparableLogger implements Comparable
{
    private Logger logger = null;

    /**
     * Indicates that loggers should be sorted by Name only,
     *  if set to false
     * then sort is done by Level then name.
     */
    public static boolean orderByNameOnly = true;

    public ComparableLogger()
    {

    }

    public ComparableLogger(Logger logger)
    {
        this.logger = logger;
    }

    public Logger getLogger()
    {
        return logger;
    }

    public void setLogger(Logger logger)
    {
        this.logger = logger;
    }

    @Override
    public int compareTo(ComparableLogger lgrIn)
    {
        if (!orderByNameOnly &&
            logger.getEffectiveLevel().toInt() !=
                lgrIn.getLogger().getEffectiveLevel().toInt())
        {
            return (logger.getEffectiveLevel().toInt() <
                lgrIn.getLogger().getEffectiveLevel().toInt()) ? -1 : 1;
        }
        else return logger.getName().compareTo(lgrIn.getLogger().getName());
    }

    /**
     * Exposes the Loggers EffectiveLevel value to the front end for use in
     * form.
     *
     * @return
     */
    public int getLevelInt()
    {
        return this.logger.getEffectiveLevel().toInt();
    }

    /**
     * Sets the loggers actual Level to provided value if it changed.
     *
     * @param newVal
     */
    public void setLevelInt(int newVal)
    {
        if (logger.getEffectiveLevel().toInt() != newVal)
           this.logger.setLevel(Level.toLevel(newVal));
    }

    public String getLoggerName()
    {
        return this.logger.getName();
    }
}


manageLogger.xhtml



<?xml version='1.0' encoding='UTF-8' ?>
<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN"
                      "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">
<html xmlns="http://www.w3.org/1999/xhtml"
      xmlns:ui="http://java.sun.com/jsf/facelets"
      xmlns:f="http://java.sun.com/jsf/core"
      xmlns:h="http://java.sun.com/jsf/html"
      xmlns:a4j="http://richfaces.org/a4j"
      xmlns:rich="http://richfaces.org/rich"
      xmlns:t="http://myfaces.apache.org/tomahawk"
      xmlns:c="http://java.sun.com/jstl/core">

<ui:composition template="../templates/template.xhtml">
<ui:define name="pageTitle"><h:outputText value="#{msg['manageLogger.page.title']}"/></ui:define>
<ui:define name="pageSubTitle"><h:outputText value="#{msg['manageLogger.page.subtitle']}"/></ui:define>
<ui:define name="content">
<h:form id="form">


<rich:messages id="pageMessages" globalOnly="true" infoClass="rich-messages-info" errorClass="rich-messages-error"/>

<a4j:outputPanel id="loggerPanel">
<table id="loggerTable" border="0" cellspacing="0" cellpadding="3">  
<tr>
    <td colspan ="2">
    <table>
        <tr><td colspan="3"><b><h:outputLabel value="#{msg['label.newlogger']}" title="#{msg['label.newlogger']}" style="padding-top:6px;height:20px;"/></b></td></tr>
        <tr><td colspan="3"><h:outputLabel value="#{msg['label.loggername']}:" title="#{msg['label.loggername']}" style="padding-top:6px;height:20px;"/></td>
            <td><h:inputText id="newLoggerName" value="#{loggerAdmin.newLoggerName}" style="width:200px;"/></td>
            <td>
                <h:selectOneMenu id="newLogLevel" value="#{loggerAdmin.newLogLevel}" >
                        <t:selectItems value="#{loggerAdmin.logLevels}" var="lvl" itemLabel="#{lvl.name}" itemValue="#{lvl.value}" />
                </h:selectOneMenu>
            </td></tr>
        <tr><td colspan="3"><a4j:commandButton id="add" action="#{loggerAdmin.processAdd}" style="width:75px; margin-right:6px;" value="#{msg['label.ok']}" reRender="loggerPanel"/></td></tr>
    </table>
    </td>
</tr>
<ui:repeat var="logger" value="#{loggerAdmin.activeLoggers}">
<tr>  
    <td align="right" valign="top"><h:outputLabel value="#{logger.logger.name}:" title="#{logger.logger.name}" style="font-size:150%;padding-top:6px;height:20px;"/></td>
    <td align="left">
        <h:selectOneMenu id="level" value="#{logger.levelInt}" >
            <t:selectItems value="#{loggerAdmin.logLevels}" var="lvl" itemLabel="#{lvl.name}" itemValue="#{lvl.value}" />
            <a4j:support event="onchange" action="#{loggerAdmin.processUpdate}">
              
            </a4j:support>
        </h:selectOneMenu> <rich:message for="level"/>
    </td>
</tr>
</ui:repeat>

</table>
</a4j:outputPanel>
<br/>

</h:form>

</ui:define>
</ui:composition>
</html>


H2 Database, Junit and Sequence Problems.

Running my Junit tests against a disposable local database has saved me a lot of trouble but, it has given me a couple of problems as well.

I'm quite pleased with how I can bring up a fresh H2 database when I start an JUnit test. I have built a simple JUnit Abstract class which manages the H2 setup loading the DDL for my database followed by sql files that are specific to each unit test (The latter being called from an @BeforeClass method calls a parent method with the path of the unit tests sql inserts. This gives me the ability to seed the database with good test data against which I can run my tests. By doign this I ensure that the data in the database is always exactly what it should be while the test is running. If you have ever tried to run tests against a standing dev database you know it rapidly becomes populated with all sorts of junk from other developers testing or even your own code. With this approach your data is always in a known state, problem solved!

I like H2 and its very useful but,I have come across a couple of oddities using while using it as part of my testing structure. First, while H2 is Oracle compliant if accessed with mode=oracle on the JDBC URL, there are still some DDL and SQL commands which aren't supported, to_date() being a big one.

This is unfortunate since you also want to run your tests against a current database structure and if your in an agile environment with a new database in the works your DB is changing as often as your code! I got around that issue by building a Processor that simply converts all SQL into a compliant format discarding statements that are not usable. Thanks to this processor I can then dump DDL from Toad and simply load up the table export for testing. Nice!

The other notable issue I encountered when implementing this testing framework is encountered when processing the seed data sql. The following simple insert statements creates unexpected SQL errors:

INSERT INTO MY_TABLE (id, some_field, some_other_field) VALUES(MY_TABLE_SEQ.nextval, 'value', 'value');

Note the usage of the sequence call to nextval:  MY_TABLE_SEQ.nextval

For whatever reason this call simply doesn't work. You will receive a SQL error informing you of Primary Key violation requiring a unique id. Yea you SHOULD be inserting one from the sequence but, the H2 sequence is not incremented by the call and you get an old sequence number!

The solution is really quite simple but, sent me on a bit of a hunt trying to figure out what was amiss. In an effort to save someone else a chunk of time here is the solution:

SELECT MY_TABLE_SEQ.nextval from DUAL;
INSERT INTO MY_TABLE (id, some_field, some_other_field) VALUES(MY_TABLE_SEQ.currval, 'value', 'value');

Told you it was simple! I almost feel silly for having spent so much time trying to debug my code! As long as you give H2 a chance to commit a sequence increment, the problem is solved. This works great for testing and solves my problem.

It does imply that there could be issues in H2 if you are doing multiple user inserts and incrementing that sequence so if your in this sort of situation keep your eye out for issues. Fortunately it doesn't effect my local JUnits!

Hey there!

Since this is my first post it seems reasonable to jot down a quick comment about the purpose of my blog and what I hope to write here. I have a somewhat unhealthy interest in technology and software development, its what I do for  a living and frequently what I do for fun. Because of this I get around a good bit and just want to share what I pick up along the way. In a more selfish light I want to record my experiences so I can go back a year later and check out what I learned because inevitably I'll need to know it a year after I forget it and have lost all my notes, assuming there were any notes!

I have been hacking computers since I found out I could reprogram my favorite games on the Apple IIe back in the day. These days I am most interested in open source and Linux as well as just about any viable language I can use to make these technologies more fun. Additional technological fascinations include the Android platform and social media technologies. I get into the code but I also find the theoretical and the implications of new technology interesting and love to speculate.

I will try to stay on target, in a topical since but, since I am focusing on "technology" that can include a smattering of Sci-fi discussion and other general topics of geekdom.

Coming up shortly, H2 database, Facebook GraphAPI and a Log4j trick.