Logging

I have a bit of time to burn, so lets talk about logging.

log
Log ! (from BLAMMO!) You must click this link.
log·ging
Pronunciation: /ˈlôgiNG/

And because this is a nerd blog, that’d be

Noun
The creation of a register of the operation of a machine.

    … and not

Noun
The activity or business of felling trees and cutting and preparing the timber..

Logging is great, you should do more of it, especially just before your application crashes and people expect you to be able to recreate your database from the contents of it.

What’s that ? You didn’t log every non-password input field that people type into your site ?

Good luck explaining to your unhappy boss / customer that the reason they can’t create an account on your travel / entertainment / fishing / adventure / finance / social / cheese-making website is because they can’t type an email address in properly.

If you didn’t log it, it didn’t happen.

Log files also have the nice property that they’re usually just composed of line-delimited unstructured data, which makes it perfect for people to put them into NoSQL datastores and fail to do JOINs on them.

I use log4j, which is what everyone else in the world uses, except for those people who use java.util.logging (jul), and/or those people who use apache commons logging or slf4j.

But they just end up wrapping log4j anyway, so let’s just ignore those weirdos.

Logging has possibly the simplest API that you’re likely to come across (usually along the lines of logger.debug("Contented burbling")), so everyone thinks they can do it slightly better.

What if you had finer levels of logging granularity, allowing even more contented burbling ?

What if you removed the log4j dependency ?

What if you create yet another API wrapping all the other APIs that everyone else has wrapped around log4j ?

What if you introduced heretofore unprecedented levels of indirection in your configuration files ?

and so on.

Some useful classes that aren’t included in the standard log4j distribution that I end up using regularly are:

  • Log4jCliConfiguration which I use in command-line interface (CLI) programs to initialise log4j relatively sanely. See the source code below for the defaults I use. They can be overridden by supplying a Properties object conforming to the standard log4j properties format.
  • MemoryAppender which I use to create an in-memory list of recent logging events (usually to allow dumping to a webpage for debugging), saving you the hassle of actually logging onto the machine to view the logs.

and so, through the goodness and altruism that comes with releasing yet more code into the world, I give you the surprisingly unit-tested Log4jCliConfiguration class:

Log4jCliConfiguration.java
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
package com.randomnoun.common.log4j;
 
/* (c) 2013 randomnoun. All Rights Reserved. This work is licensed under a
 * BSD Simplified License. (http://www.randomnoun.com/bsd-simplified.html)
 */
 
import java.util.Properties;
 
import org.apache.log4j.PropertyConfigurator;
 
/** Configures log4j for command-line interface programs.
 * 
 * <p>By default, everything's sent to stdout, using the following log4j initilisation properties:
 * 
 * <pre>
log4j.rootCategory=DEBUG, CONSOLE
log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.layout.ConversionPattern=%d{ABSOLUTE} %-5p %c - %m %n
 
log4j.logger.org.springframework=INFO
 
# log4j.appender.FILE=com.randomnoun.common.log4j.CustomRollingFileAppender
# log4j.appender.FILE.File=c:\\eomail.log
# log4j.appender.FILE.MaxBackupIndex=100
# log4j.appender.FILE.layout=org.apache.log4j.PatternLayout
# log4j.appender.FILE.layout.ConversionPattern=%d{dd/MM/yy HH:mm:ss.SSS} %-5p %c - %m %n
   </pre>
 * 
 * <p>with an optional line prefix before the <code>%d{ABSOLUTE}</code> in the ConversionPattern.
 * 
 * @see http://logging.apache.org/log4j/1.2/manual.html
 * 
 * <p>TODO: Support XML-based configurators
 * 
 * @blog http://www.randomnoun.com/wp/2013/01/13/logging/
 * @author knoxg
 * @version $Id: Log4jCliConfiguration.java,v 1.3 2013-09-24 02:37:09 knoxg Exp $
 */
public class Log4jCliConfiguration {
    /** A revision marker to be used in exception stack traces. */
    public static final String _revision = "$Id: Log4jCliConfiguration.java,v 1.3 2013-09-24 02:37:09 knoxg Exp $";
 
	/** Create a new Log4jCliConfiguration instance */
	public Log4jCliConfiguration() {
	}
 
	/** Initialise log4j.
	 * 
	 * @param logFormatPrefix a string prefixed to each log. Useful for program identifiers;
	 *   e.g. "[programName] "
	 * @param override if non-null, additional log4j properties. Any properties contained in 
	 *   this object will override the defaults.
	 * 
	 */
	public void init(String logFormatPrefix, Properties override) {
 
		if (logFormatPrefix==null) { 
			logFormatPrefix = ""; 
		} else {
			logFormatPrefix += " ";
		}
 
		Properties lp = new Properties();
		lp.put("log4j.rootCategory", "DEBUG, CONSOLE");
		lp.put("log4j.appender.CONSOLE", "org.apache.log4j.ConsoleAppender");
		lp.put("log4j.appender.CONSOLE.layout", "org.apache.log4j.PatternLayout");
		lp.put("log4j.appender.CONSOLE.layout.ConversionPattern", logFormatPrefix + "%d{ABSOLUTE} %-5p %c - %m%n");
 
		lp.put("log4j.logger.org.springframework", "INFO"); // since Spring is a bit too verbose for my liking at DEBUG level
 
		/*
		lp.put("log4j.appender.FILE", "com.randomnoun.common.log4j.CustomRollingFileAppender");
		lp.put("log4j.appender.FILE.File", "c:\\eomail.log");
		lp.put("log4j.appender.FILE.MaxBackupIndex", "100");
		lp.put("log4j.appender.FILE.layout", "org.apache.log4j.PatternLayout");
		lp.put("log4j.appender.FILE.layout.ConversionPattern", "%d{dd/MM/yy HH:mm:ss.SSS} %-5p %c - %m %n");
		*/
 
 
		if (override!=null) { lp.putAll(override); }
		PropertyConfigurator.configure(lp);
	}
}
Log4jCliConfigurationTest.java
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
package com.randomnoun.common.log4j;
 
/* (c) 2013 randomnoun. All Rights Reserved. This work is licensed under a
 * BSD Simplified License. (http://www.randomnoun.com/bsd-simplified.html)
 */
 
import java.io.ByteArrayOutputStream;
import java.io.PrintStream;
import java.util.Properties;
 
import org.apache.log4j.Logger;
 
import com.randomnoun.common.log4j.Log4jCliConfigurationTest;
 
import junit.framework.TestCase;
 
/**
 * Unit test for Log4jCliConfigurationTest
 *
 * @blog http://www.randomnoun.com/wp/2013/01/13/logging/
 * @version $Id: Log4jCliConfigurationTest.java,v 1.3 2013-09-24 02:37:09 knoxg Exp $
 * @author knoxg
 */
public class Log4jCliConfigurationTest
	extends TestCase
{
 
	ByteArrayOutputStream baos;
	PrintStream stdout; 
	PrintStream out;
 
	/** Redirect System.out to something we can inspect
	 */
	protected void setUp() {
		baos = new ByteArrayOutputStream();
		out = new PrintStream(baos);
		stdout = System.out;
		System.setOut(out);
	}
 
	/**
	 */
	protected void tearDown()
	{
		// reset System.out back to stdout
		System.setOut(stdout);
	}
 
	public void testNoLogPrefix() {
		// CRLFs on windows
		String lineSeparator = System.getProperty("line.separator");		
		String regex, line;
 
		Log4jCliConfiguration lcc = new Log4jCliConfiguration();
		lcc.init(null, null);
		Logger logger = Logger.getLogger("testLogger");
 
		logger.info("info message");
		regex = "^[0-9]{2}:[0-9]{2}:[0-9]{2},[0-9]{3} INFO  testLogger - info message$";
		line = baos.toString().split(lineSeparator)[0];
		// should look something like "06:52:08,156 INFO  testLogger - info message"
		assertTrue("String '" + line + "' does not match regex '" + regex + "'", line.matches(regex));
 
		logger.debug("debug message");
		regex = "^[0-9]{2}:[0-9]{2}:[0-9]{2},[0-9]{3} DEBUG testLogger - debug message$";
		line = baos.toString().split(lineSeparator)[1];
		assertTrue("String '" + line + "' does not match regex '" + regex + "'", line.matches(regex));
	}
 
	public void testWithPrefix() {
		// CRLFs on windows
		String lineSeparator = System.getProperty("line.separator");		
		String regex, line;
 
		Log4jCliConfiguration lcc = new Log4jCliConfiguration();
		lcc.init("[Log4jCliConfigurationTest]", null);
		Logger logger = Logger.getLogger("testLogger");
 
		logger.info("info message");
		regex = "^\\[Log4jCliConfigurationTest\\] [0-9]{2}:[0-9]{2}:[0-9]{2},[0-9]{3} INFO  testLogger - info message$";
		line = baos.toString().split(lineSeparator)[0];
		// should look something like "06:52:08,156 INFO  testLogger - info message"
		assertTrue("String '" + line + "' does not match regex '" + regex + "'", line.matches(regex));
 
		logger.debug("debug message");
		regex = "^\\[Log4jCliConfigurationTest\\] [0-9]{2}:[0-9]{2}:[0-9]{2},[0-9]{3} DEBUG testLogger - debug message$";
		line = baos.toString().split(lineSeparator)[1];
		assertTrue("String '" + line + "' does not match regex '" + regex + "'", line.matches(regex));
	}
 
	public void testPropertiesOverride() {
		// CRLFs on windows
		String lineSeparator = System.getProperty("line.separator");		
		String regex, line;
 
		Log4jCliConfiguration lcc = new Log4jCliConfiguration();
		Properties props = new Properties();
		props.put("log4j.rootCategory", "INFO, CONSOLE");  // set default threshold to 'INFO' level
		lcc.init("[Log4jCliConfigurationTest]", props);
		Logger logger = Logger.getLogger("testLogger");
 
		logger.info("info message");
		regex = "^\\[Log4jCliConfigurationTest\\] [0-9]{2}:[0-9]{2}:[0-9]{2},[0-9]{3} INFO  testLogger - info message$";
		line = baos.toString().split(lineSeparator)[0];
		// should look something like "06:52:08,156 INFO  testLogger - info message"
		assertTrue("String '" + line + "' does not match regex '" + regex + "'", line.matches(regex));
 
		logger.debug("debug message");
		assertTrue("debug message should have been suppressed", 
			baos.toString().split(lineSeparator).length==1);
	}
 
}

with which you can do things like this:

Log4jCliExample.java
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
package com.example.contrived.cli;
 
/* (c) 2013 randomnoun. All Rights Reserved. This work is licensed under a 
 * <a rel="license" href="http://creativecommons.org/licenses/by/3.0/">Creative Commons Attribution 3.0 Unported License</a>.
 */
 
import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.TimeZone;
 
import org.apache.log4j.Logger;
 
import com.randomnoun.common.log4j.Log4jCliConfiguration;
 
/** This program tells you what time it is in Antarctica.
 * 
 * <p>It will return with an exit-code of zero if successful, 1 otherwise.
 *
 * @blog http://www.randomnoun.com/wp/2012/12/26/something
 * @version $Id: Log4jCliExample.java,v 1.3 2013-01-13 12:28:03 knoxg Exp $
 * @author knoxg
 */
public class Log4jCliExample {
 
	/** Logger instance for this class */
	static Logger logger = Logger.getLogger(Log4jCliExample.class);
 
 
	/** Command-line interface.
	 * 
	 * @param args command-line arguments
	 */
	public static void main(String args[]) {
		try {
			Log4jCliConfiguration lcc = new Log4jCliConfiguration();
			lcc.init("[Log4jCliExample]", null);
 
			Date now = new Date();
			SimpleDateFormat sdf = new SimpleDateFormat("EEE dd/MMM/yyyy HH:mm:ss Z");
 
			sdf.setTimeZone(TimeZone.getTimeZone("Antarctica/Mawson"));
			logger.info("Taking into consideration the change in timezone in 2009,");
			logger.info("The time at the Australian Mawson Station in ");
			logger.info("Antarctica is currently " + sdf.format(now));
			logger.info("");
 
			sdf.setTimeZone(TimeZone.getTimeZone("Antarctica/Palmer"));
			logger.info("Whereas on the other side of the planet in Palmer Station,");
			logger.info("Antarctica, they keep the same time as Punta Arenas, Chile,");
			logger.info("because, that's the other end of their supply line.");
			logger.info("Prior to that, before the Falklands War in May 1982,");
			logger.info("Palmer used to be supplied from Argentina.");
			logger.info("The time at Palmer Station is currently " + sdf.format(now));
 
		} catch (Exception e) {
			logger.error("Exception in main", e);
			System.exit(1);
		}
 
		System.exit(0);
 
	}
}

which generates this (there’s a scrollbar there which you can click and drag to see more words magically appear):

[Log4jCliExample] 07:07:32,359 INFO  com.example.contrived.cli.Log4jCliExample - Taking into consideration the change in timezone in 2009, 
[Log4jCliExample] 07:07:32,359 INFO  com.example.contrived.cli.Log4jCliExample - The time at the Australian Mawson Station in  
[Log4jCliExample] 07:07:32,359 INFO  com.example.contrived.cli.Log4jCliExample - Antarctica is currently Sat 12/Jan/2013 02:07:32 +0500 
[Log4jCliExample] 07:07:32,359 INFO  com.example.contrived.cli.Log4jCliExample -  
[Log4jCliExample] 07:07:32,359 INFO  com.example.contrived.cli.Log4jCliExample - Whereas on the other side of the planet in Palmer Station, 
[Log4jCliExample] 07:07:32,359 INFO  com.example.contrived.cli.Log4jCliExample - Antarctica, they keep the same time as Punta Arenas, Chile, 
[Log4jCliExample] 07:07:32,359 INFO  com.example.contrived.cli.Log4jCliExample - because, that's the other end of their supply line. 
[Log4jCliExample] 07:07:32,359 INFO  com.example.contrived.cli.Log4jCliExample - Prior to that, before the Falklands War in May 1982, 
[Log4jCliExample] 07:07:32,359 INFO  com.example.contrived.cli.Log4jCliExample - Palmer used to be supplied from Argentina. 
[Log4jCliExample] 07:07:32,359 INFO  com.example.contrived.cli.Log4jCliExample - The time at Palmer Station is currently Fri 11/Jan/2013 18:07:32 -0300

which you’ll note has a

  • a standard line prefix (“[Log4jCliExample]” and the current time), followed by
  • the logging level (usually one of DEBUG, INFO, WARN, ERROR, FATAL),
  • the name of the java class doing the logging,
  • and the log message.

You probably want to add thread ids, usernames and other markers to your logging in order to more accurately allocate blame for when you need to read these logs. (I use a servlet filter to set a log4j MDC variable with the current username, but you can use whatever you have lying around the home).

The timestamps in the standard prefix are all in the local server time, which, if you have a bit of forethought, you might want to set to UTC.

This will make co-ordinating your geographically dispersed automated system for collecting pictures of cats and selfies that much easier.

A Softer World: 1040

So. Where was I ? Ah yes. Here’s the MemoryAppender code and unit test:

MemoryAppender.java
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
package com.randomnoun.common.log4j;
 
/* (c) 2013 randomnoun. All Rights Reserved. This work is licensed under a
 * BSD Simplified License. (http://www.randomnoun.com/bsd-simplified.html)
 */
 
import java.util.*;
 
import org.apache.log4j.*;
import org.apache.log4j.spi.LoggingEvent;
 
 
/**
 * Log4j appender to capture logging events in an in-memory List. I'm amazed
 * this isn't in the log4j package.
 *
 * <p>The code in this class is roughly based on the WriterAppender class
 * in the log4j source code.
 * 
 * <p>This appender can be configured using the property "maximumLogSize" 
 * which limits the number of logging events captured by this class (old events
 * are popped off the list when the list becomes full).
 * 
 * <p>Use the {@link #getLoggingEvents()} to return the List of events written
 * to this class. This list is a *copy* of the list contained within this class,
 * so it can safely be iterated over even if logging events are still
 * occurring in an application.
 * 
 * <p>Example log4j configuration:
 * <pre class="code">
 * log4j.rootLogger=DEBUG, MEMORY
 * 
 * log4j.appender.MEMORY=com.randomnoun.common.log4j.MemoryAppender
 * log4j.appender.MEMORY.MaximumLogSize=1000
 * </pre>
 * 
 * You can then obtain the list of events via the code:
 * <pre>
 * MemoryAppender memoryAppender = (MemoryAppender) Logger.getRootLogger().getAppender("MEMORY");
 * List events = memoryAppender.getEvents();
 * </pre>
 *
 * @blog http://www.randomnoun.com/wp/2013/01/13/logging/
 * @version $Id: MemoryAppender.java,v 1.3 2013-09-24 02:37:09 knoxg Exp $
 * @author knoxg
 */
public class MemoryAppender
    extends AppenderSkeleton
{
    /** A revision marker to be used in exception stack traces. */
    public static final String _revision = "$Id: MemoryAppender.java,v 1.3 2013-09-24 02:37:09 knoxg Exp $";
 
    public final static long DEFAULT_LOG_SIZE = 1000;
    private long maximumLogSize = DEFAULT_LOG_SIZE;
    private LinkedList<LoggingEvent> loggingEvents;
 
    /** Create a new MemoryAppender object */
    public MemoryAppender()
    {
        // this should be a LinkList since we use this data structure as a queue
        loggingEvents = new LinkedList<LoggingEvent>();
    }
 
    /** Create a new MemoryAppender with the specified log size
     * 
     * @param logSize The maximum number of logging events to store in this class 
     */ 
    public MemoryAppender(int logSize)
    {
        this.maximumLogSize = logSize;
        // this should be a LinkList since we use this data structure as a queue
        loggingEvents = new LinkedList<LoggingEvent>();
    }
 
    /** Immediate flush is always set to true, regardless of how
     *  this logger is configured. 
     *
     * @param value ignored
     */
    public void setImmediateFlush(boolean value)
    {
        // this method does nothing
    }
 
    /** Returns value of the <b>ImmediateFlush</b> option. */
    public boolean getImmediateFlush()
    {
        return true;
    }
 
    /** Set the maximum log size */
    public void setMaximumLogSize(long logSize)
    {
        this.maximumLogSize = logSize;
    }
 
    /** Return the maximum log size */
    public long getMaximumLogSize()
    {
        return maximumLogSize;
    }
 
    /** This method does nothing. 
     */
    public void activateOptions()
    {
    }
 
    /**
       This method is called by the {@link AppenderSkeleton#doAppend}
       method.
       <p>If the output stream exists and is writable then write a log
       statement to the output stream. Otherwise, write a single warning
       message to <code>System.err</code>.
       <p>The format of the output will depend on this appender's
       layout.
     */
    public void append(LoggingEvent event)
    {
        // Reminder: the nesting of calls is:
        //
        //    doAppend()
        //      - check threshold
        //      - filter
        //      - append();
        //        - checkEntryConditions();
        //        - subAppend();
        if (!checkEntryConditions())
        {
            return;
        }
 
        subAppend(event);
    }
 
    /**
       This method determines if there is a sense in attempting to append.
       <p>It checks whether there is a set output target and also if
       there is a set layout. If these checks fail, then the boolean
       value <code>false</code> is returned. 
 
       <p>This method always returns true; which I guess means we can't have
       thresholds set on our MemoryAppender.
     */
    protected boolean checkEntryConditions()
    {
        /*
           if (this.layout == null)
           {
               errorHandler.error("No layout set for the appender named [" + name + "].");
               return false;
           } */
        return true;
    }
 
    /** Close this appender instance. The event log list is cleared by this method. 
     * This method is identical to calling clear()
     */
    public synchronized void close()
    {
        loggingEvents.clear();
    }
 
    /** Clear all events from this appender. */
    public synchronized void clear() 
    {
		synchronized(loggingEvents) {
			loggingEvents.clear();
		}
    }
 
    /** Actual appending occurs here. */
    protected void subAppend(LoggingEvent event)
    {
        // this.qw.write(this.layout.format(event));
        synchronized(loggingEvents) {
	        if (loggingEvents.size() >= maximumLogSize)
	        {
	            loggingEvents.removeLast();
	        }
 
	        loggingEvents.addFirst(event);
        }
    }
 
    /**
       The MemoryAppender does not require a layout. Hence, this method returns
       <code>false</code>.
     */
    public boolean requiresLayout()
    {
        return false;
    }
 
    /** Returns a list of logging events captured by this appender. (This list 
     *  is cloned in order to prevent ConcurrentModificationExceptions occuring
     *  whilst iterating through it) */
    public List<LoggingEvent> getLoggingEvents()
    {
        return new ArrayList<LoggingEvent>(loggingEvents);
    }
}
MemoryAppenderTest.java
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
package com.randomnoun.common.log4j;
 
/* (c) 2013 randomnoun. All Rights Reserved. This work is licensed under a
 * BSD Simplified License. (http://www.randomnoun.com/bsd-simplified.html)
 */
 
import java.util.List;
import java.util.Properties;
 
import org.apache.log4j.Level;
import org.apache.log4j.LogManager;
import org.apache.log4j.Logger;
import org.apache.log4j.PropertyConfigurator;
import org.apache.log4j.spi.LoggingEvent;
 
import com.randomnoun.common.log4j.MemoryAppenderTest;
 
import junit.framework.TestCase;
 
/**
 * Unit test for Log4jCliConfigurationTest
 * 
 * @blog http://www.randomnoun.com/wp/2013/01/13/logging/
 * @version $Id: MemoryAppenderTest.java,v 1.3 2013-09-24 02:37:09 knoxg Exp $
 * @author knoxg
 */
public class MemoryAppenderTest
	extends TestCase
{
 
	/** Reset log4j before each test
	 */
	protected void setUp() {
		LogManager.resetConfiguration();
	}
 
	/**
	 */
	protected void tearDown()
	{
	}
 
	public void testMemoryAppenderViaProperties() {
 
		Properties props = new Properties();
		props.put("log4j.rootCategory", "INFO, MEMORY");
		props.put("log4j.appender.MEMORY", "com.randomnoun.common.log4j.MemoryAppender");
		// layouts have no effect on MemoryAppenders
		//props.put("log4j.appender.MEMORY.layout", "org.apache.log4j.PatternLayout");
		//props.put("log4j.appender.MEMORY.layout.ConversionPattern", "%d{dd/MM/yy HH:mm:ss.SSS} %-5p %c - %m%n");
		props.put("log4j.appender.MEMORY.MaximumLogSize", 100);
		PropertyConfigurator.configure(props);
 
		Logger logger = Logger.getLogger("testLogger");
		MemoryAppender memoryAppender = (MemoryAppender) Logger.getRootLogger().getAppender("MEMORY");
		List<LoggingEvent> loggingEvents;
 
		long start = System.currentTimeMillis();
		logger.info("info message");
		long end = System.currentTimeMillis();
 
		loggingEvents = memoryAppender.getLoggingEvents();
		assertTrue("info message in memoryAppender", loggingEvents.size()==1);
		assertEquals("info message", loggingEvents.get(0).getMessage());
		assertEquals("info message", loggingEvents.get(0).getRenderedMessage());
		assertNotNull(loggingEvents.get(0).getLoggerName());
		assertEquals(Level.INFO, loggingEvents.get(0).getLevel());
		// NB: timestamp field requires log4j 1.2.15
		assertTrue("timestamp of loggingEvent >= start", loggingEvents.get(0).getTimeStamp() >= start);
		assertTrue("timestamp of loggingEvent <= end", loggingEvents.get(0).getTimeStamp() <= end);
 
		logger.debug("debug message");
		loggingEvents = memoryAppender.getLoggingEvents();
		assertTrue("debug message suppressed from memoryAppender", loggingEvents.size()==1);
 
	}
 
	public void testMemoryAppenderViaObjectModel() {
		Logger logger = Logger.getLogger("testLogger");
		Logger.getRootLogger().setLevel(Level.INFO);
		MemoryAppender memoryAppender = new MemoryAppender();
		logger.removeAllAppenders();
		logger.addAppender(memoryAppender);
 
		List<LoggingEvent> loggingEvents;
 
		long start = System.currentTimeMillis();
		logger.info("info message");
		long end = System.currentTimeMillis();
 
		loggingEvents = memoryAppender.getLoggingEvents();
		assertTrue("info message in memoryAppender", loggingEvents.size()==1);
		assertEquals("info message", loggingEvents.get(0).getMessage());
		assertEquals("info message", loggingEvents.get(0).getRenderedMessage());
		assertNotNull(loggingEvents.get(0).getLoggerName());
		assertEquals(Level.INFO, loggingEvents.get(0).getLevel());
		// NB: timestamp field requires log4j 1.2.15
		assertTrue("timestamp of loggingEvent >= start", loggingEvents.get(0).getTimeStamp() >= start);
		assertTrue("timestamp of loggingEvent <= end", loggingEvents.get(0).getTimeStamp() <= end);
 
		logger.debug("debug message");
		loggingEvents = memoryAppender.getLoggingEvents();
		assertTrue("debug message suppressed from memoryAppender", loggingEvents.size()==1);
	}
 
	public void testLogWindowSize() {
 
		// create a MemoryLogger capable of holding 10 entries
 
		Properties props = new Properties();
		props.put("log4j.rootCategory", "INFO, MEMORY");
		props.put("log4j.appender.MEMORY", "com.randomnoun.common.log4j.MemoryAppender");
		props.put("log4j.appender.MEMORY.MaximumLogSize", "10");
		PropertyConfigurator.configure(props);
 
		Logger logger = Logger.getLogger("testLogger");
		MemoryAppender memoryAppender = (MemoryAppender) Logger.getRootLogger().getAppender("MEMORY");
		List<LoggingEvent> loggingEvents;
 
		// write five messages. 
		// the 0th message in MemoryAppender should be the most recent (i.e. message #5)
		for (int i=1; i<=5; i++) {
			logger.info("message number " + i);
		}
		loggingEvents = memoryAppender.getLoggingEvents();
		assertTrue("5 info messages in memoryAppender", loggingEvents.size()==5);
		for (int i=0; i<5; i++) {
			assertEquals("message number " + (5 - i), loggingEvents.get(i).getRenderedMessage());
		}
 
		// write another five messages
		for (int i=6; i<=10; i++) {
			logger.info("message number " + i);
		}
		loggingEvents = memoryAppender.getLoggingEvents();
		assertTrue("10 info messages in memoryAppender", loggingEvents.size()==10);
		for (int i=0; i<10; i++) {
			assertEquals("message number " + (10 - i), loggingEvents.get(i).getRenderedMessage());
		}
 
		// write another five messages (memoryAppender should just contain messages 6-15)
		for (int i=11; i<=15; i++) {
			logger.info("message number " + i);
		}
		loggingEvents = memoryAppender.getLoggingEvents();
		System.out.println(loggingEvents.size());
		assertTrue("10 info messages in memoryAppender", loggingEvents.size()==10);
		for (int i=0; i<10; i++) {
			assertEquals("message number " + (15 - i), loggingEvents.get(i).getRenderedMessage());
		}
 
	}
 
 
}

The example servlet here will start a Timer that logs a message every second, every once in a while throwing an Exception just to keep things interesting.

It forwards to the JSP, which is responsible for displaying every LoggingEvent contained within the MemoryAppender, and contains links to reset the MemoryAppender.

In a real debug page, you probably want the ability to increase/decrease logging levels for various Logger objects, as well as tweak other log4j settings.

MemoryAppenderExampleServlet.java
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
package com.example.contrived.web.servlet;
 
/* (c) 2013 randomnoun. All Rights Reserved. This work is licensed under a 
 * <a rel="license" href="http://creativecommons.org/licenses/by/3.0/">Creative Commons Attribution 3.0 Unported License</a>.
 */
 
import java.io.IOException;
import java.util.List;
import java.util.Timer;
import java.util.TimerTask;
 
import javax.servlet.RequestDispatcher;
import javax.servlet.ServletConfig;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
 
import org.apache.log4j.Logger;
import org.apache.log4j.spi.LoggingEvent;
 
import com.example.contrived.web.config.AppConfig;
 
import com.randomnoun.common.log4j.MemoryAppender;
 
/** A servlet which just displays all messages from the MemoryAppender.
 * 
 * <p>When the servlet is initialised (usually the first time it is invoked), it will
 * start a Timer which generates a log message every second.
 * 
 * <p>This servlet will always forward to the memoryAppenderExample.jsp, which 
 * simply displays all the collected LoggingEvents in a table.
 * 
 * <p>HTTP request parameters:
 * <attributes>
 * clear - if present, will clear all events from the MemoryAppender
 * </attributes>
 *
 * <p>Note it's usually considered Bad Form to run Timers within Servlets, but this is
 * just an example.
 * 
 * @blog http://www.randomnoun.com/wp/2013/01/13/logging/
 * @version $Id: MemoryAppenderExampleServlet.java,v 1.3 2013-01-13 13:18:02 knoxg Exp $
 * @author knoxg
 */
public class MemoryAppenderExampleServlet extends HttpServlet {
 
    /** A revision marker to be used in exception stack traces. */
    public static final String _revision = "$Id: MemoryAppenderExampleServlet.java,v 1.3 2013-01-13 13:18:02 knoxg Exp $";
 
	/** Logger instance for this class */
	Logger logger = Logger.getLogger(MemoryAppenderExampleServlet.class);
 
	/** This timer is used to generate log messages every second or so */
	Timer timer;
 
	/** This task generates the log messages */
	TimerTask timerTask;
 
	/** Start the timer when the servlet is initialised */
	@Override
	public void init(ServletConfig config) throws ServletException {
		super.init(config);
		timer = new java.util.Timer();
		timerTask = new TimerTask() {
			long i = 0;
			@Override
			public void run() {
				if (Math.random()>0.9) {
					Exception e = new RuntimeException("Test exception");
					logger.info("This is log message number " + i + " with an exception", e);
				} else {
					logger.info("This is log message number " + i);
				}
				i++;
			} };
		timer.schedule(timerTask, 1000, 1000);
		logger.info("MemoryAppenderExample Timer started");
	}
 
	/** Stop the timer when the app is destroyed */
	@Override
	public void destroy() {
		super.destroy();
		timerTask.cancel();
		timer.purge();
		logger.info("MemoryAppenderExample Timer stopped");
	}
 
	/** Display a list of all logging messages from the MemoryAppender */
	@Override
	protected void doGet(HttpServletRequest request, HttpServletResponse response)
		throws ServletException, IOException 
	{
		AppConfig appConfig = AppConfig.getAppConfig(); // this will initialise log4j
		MemoryAppender appender = (MemoryAppender) Logger.getRootLogger().getAppender("MEMORY");
 
		// reset the appender if a clear parameter is present
		if (request.getParameter("clear")!=null) {
			appender.clear();
		}
 
		List<LoggingEvent> events = appender.getLoggingEvents();
		request.setAttribute("events", events);
		RequestDispatcher rd = request.getRequestDispatcher("/memoryAppenderExample.jsp");
		rd.forward(request, response);
	}
 
}
memoryAppenderExample.jsp
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
<%@ page 
  language="java"
  contentType="text/html; charset=ISO-8859-1"
  pageEncoding="ISO-8859-1"
  errorPage="misc/errorPage.jsp"
  import="java.util.*,java.text.*,org.apache.log4j.spi.LoggingEvent,com.randomnoun.common.ExceptionUtils"
%>
<%!
	/* (c) 2013 randomnoun. All Rights Reserved. This work is licensed under a 
 	 * <a rel="license" href="http://creativecommons.org/licenses/by/3.0/">Creative Commons Attribution 3.0 Unported License</a>.
 	 */
 
	/** Revision marker for use in stack traces */
	public static final String _revision = "$Id: memoryAppenderExample.jsp,v 1.3 2013-01-11 20:03:22 knoxg Exp $"; 
%>
<html>
<head>
<!-- $Id: memoryAppenderExample.jsp,v 1.3 2013-01-11 20:03:22 knoxg Exp $ -->
<title>Logging messages</title>
<style>
BODY { font-family: Arial; font-size: 10pt; }
H1 { font-family: Arial; font-size: 14pt; }
TABLE { margin-top: 10px; }
TD { font-family: Verdana; font-size: 8pt; vertical-align: top; }
</style>
</head>
<body>
<h1>Here ye, here ye. Here is a list of all known proclamations by this application.</h1>
<p><a href="memoryAppenderExample">Click here to refresh</a>
<p><a href="memoryAppenderExample?clear=Y">Click here to clear messages</a>
<table>
<%
    SimpleDateFormat sdf = new SimpleDateFormat("dd/MMM/yyyy HH:mm:ss"); // server timezone
    List<LoggingEvent> events = (List<LoggingEvent>) request.getAttribute("events");
    if (events==null || events.size()==0) {
%>
	<tr>
		<td colspan="3">No events recorded</td>
	</tr>
<%
    } else {
    	for (int i=0; i<events.size(); i++) {
	    	LoggingEvent event = events.get(i);
%>
    <tr>
    	<td><%= i %></td>
    	<td><%= sdf.format(new Date(event.getTimeStamp())) %></td>
    	<td><%= event.getLevel() %>
        <td><%= event.getRenderedMessage() %>
<%
	        Throwable exception = null;
			if (event.getThrowableInformation()!=null) {
				exception = event.getThrowableInformation().getThrowable();
			}
	        if (exception!=null) {
	    	    String exceptionText = "<br/><pre>" +  
	      	      ExceptionUtils.getStackTraceWithRevisions(exception, this.getClass().getClassLoader(),
	    		    ExceptionUtils.HIGHLIGHT_HTML, "com.randomnoun.,com.example.contrived.,org.apache.jsp.") + 
	    		  "</pre>";
	    		out.println(exceptionText);
	        }
%>
        </td>
    </tr>
<%
	    }
%>
</table>
<%
    }
%>
</body>
</html>

which will look a little bit like this in your web browser:

Output from running the example servlet

Output from running the example servlet

Which you’ll notice also uses marginally better stack traces.

So hopefully that all makes sense.

No need to thank me.

This class is now part of the com.randomnoun.common:common-public artifact, which can be directly referenced in your pom.xml from the maven central repository.

Update 25/9/2013: It’s in central now

Update 24/1/2013: Added the bit about NoSQL

One Comment

Add a Comment

Your email address will not be published. Required fields are marked *