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:
[rn-sourcecode lang=”java” src=”common-public/src/main/java/com/randomnoun/common/log4j/Log4jCliConfiguration.java” errors=”true”]
[rn-sourcecode lang=”java” src=”common-public/src/test/java/com/randomnoun/common/log4j/Log4jCliConfigurationTest.java” errors=”true”]
with which you can do things like this:
[rn-sourcecode lang=”java” src=”contrived-cli/src/main/java/com/example/contrived/cli/Log4jCliExample.java” errors=”true”]
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.
So. Where was I ? Ah yes. Here’s the MemoryAppender code and unit test:
[rn-sourcecode lang=”java” src=”common-public/src/main/java/com/randomnoun/common/log4j/MemoryAppender.java” errors=”true”]
[rn-sourcecode lang=”java” src=”common-public/src/test/java/com/randomnoun/common/log4j/MemoryAppenderTest.java” errors=”true”]
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.
[rn-sourcecode lang=”java” src=”contrived-web/src/main/java/com/example/contrived/web/servlet/MemoryAppenderExampleServlet.java” errors=”true”]
[rn-sourcecode lang=”java” src=”contrived-web/src/main/webapp/memoryAppenderExample.jsp” errors=”true”]
which will look a little bit like this in your web browser:
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.
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
About The Author
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