Logging
I have a bit of time to burn, so lets talk about logging.
And because this is a nerd blog, that’d be
… and not
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.
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:
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); } } |
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); } }
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); } } |
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:
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); } } |
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 |
[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.
So. Where was I ? Ah yes. Here’s the MemoryAppender code and unit test:
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); } } |
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); } }
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()); } } } |
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.
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); } } |
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); } }
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> |
<%@ 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:
Which you’ll notice also uses marginally better stack traces.
So hopefully that all makes sense.
No need to thank me.
Update 2021-01-09: I’ve split the old log4j 1 classes into a separate maven jar ( log4j-one )
but if you want something equivalent in log4j2, that’s in common-public:
both of which are on github:
Update 2013-01-24: Added the bit about NoSQL
Update 2013-09-25: It’s in central now
Update 2021-01-09: And github. And I’ve split the log4j one stuff into a separate artifact.
Related Posts
-
It’s all made out of pipes
3 Comments | Oct 8, 2013
-
Windows shell32 animations
3 Comments | Oct 27, 2013
-
Boxes and Lines
No Comments | Oct 2, 2013
-
Bitrot
No Comments | Sep 15, 2013
I have experimented with how much you can do with the standard java and found that the built in java logging is fine. A very small application with no dependencies might use it. With Java 6 many powerful web service features were introduced (so less dependencies) and they use the standard logging. For anything non-trivial you will have open source dependencies that will use log4j. It is unlikley your production log file monitoring software will cope with both formats.
Only took me ten years to respond, but hey.
Re ‘It is unlikley your production log file monitoring software will cope with both formats.’
(a) You can’t control which logging framework third-party libraries decide to use, so you still need to configure those frameworks to log through to your “primary” logging framework, whether that’s JUL, SLF4J, ACL, log4j, or some other framework. I don’t think any particular framework is any more compelling than the other, but log4j was there first, so I’ve stuck with log4j. If you want to use JUL that’s fine by me.
(b) Once you’ve configured all the other frameworks to log to your primary logging framework, all your real appenders / formatters get configured there, so you shouldn’t have multiple formats being monitored by production log monitoring.
(c) Production log monitoring that can’t handle more than one format isn’t really production log monitoring in my book