I saw a plaintive wail on Twitter about using GMail as the smtp server to send error emails using a Log4j SMTPAppender in Grails. It turned out to be a little tricky (and a bigger solution than 140 characters would allow) so I thought I'd describe the process here.

Most of the properties are configurable as appender attributes (e.g. server name, auth username, etc.) but two important ones aren't. SMTPAppender creates a Properties instance with System.getProperties() as the default values and adds smtp properties to that. But you need to specify the smtp port (it will default to 25 otherwise) and you need to tell it to send a STARTTLS command. Both are configurable via system properties:

and if you add those calls to Config.groovy before the appender is instantiated then it will have the values available when it configures its JavaMail Session:

I've parameterized the properties to make them configurable for each environment or using an external configuration file.

Note that GMail has a limit of 500 emails per day, so if you generate a lot of errors in your app you could hit that limit.

Everybody knows about wrapping Log4j log.debug() statements in if (log.isDebugEnabled()) {} blocks to make sure that the message being sent to the log method isn't evaluated unnecessarily if the DEBUG level isn't enabled for the logger. This is true in regular Java apps as well as Groovy/Grails apps.

For example, suppose you have large Collection foo and you log it with a logger whose level is set to INFO:

This will concatenate "foo is " with foo.toString() but then discard the combined string since the logger isn't at the DEBUG level. If there are a lot of these debug statements in your code then you'll waste a lot of cycles concatenating strings, especially if you're logging in loops. This is trivially fixed with this though:

But if there's no string concatenation and evaluation, then you don't need to wrap the call - the cost of a discarded log() invocation is about the same as the isDebugEnabled() test;

incurs next to zero overhead.

Enter Groovy. What happens if you use a GString, e.g.:

It turns out that this needs to be wrapped also, since although GStrings are lazy evaluated, they must be converted to a String for the debug() invocation, so you're right back where you started. To test this, try out this code in a Groovy/Grails console.

Note that to test whether toString() is called there's a println statement in toString():

When running this the output to the shell is

[2344] foo Error: Thing: a thing

and in the console is

calling thing tostring

so it didn't log the debug message, but it did log the error message since it's above the INFO level that the logger is set at. But it only printed the message from the toString() method once, meaning it didn't evaluate the GString in the debug message. Hmmm.

Turns out I was wrong in an earlier assumption - the signatures of the various Logger methods take an Object, not a String, e.g.

public void debug(Object message)

and

public void debug(Object message, Throwable t)

So there's nothing to evaluate, and the GString is discarded. Cool - Groovy to the rescue, no performance issues with logging GStrings.

I wondered though what it would take to coerce a GString to a String:

This doesn't; nothing gets printed:

log.debug "Debug: Thing: $thing" + " now"

This also doesn't, since it's concatenating two GStrings:

log.debug "Debug: Thing: $thing at " + "${System.currentTimeMillis()}"

This does trigger toString() since it's no longer concatenating strings:

log.debug "Debug: Thing: $thing at " + System.currentTimeMillis()

and of course

String message = "Debug: Thing: $thing"
log.debug message

triggers toString() since it explicitly creates a String.

So it turns out that you'd pretty much have to work at causing a performance issue with logging GStrings.

Proper logging implementation is a complex issue. If you log too much in production you risk wasting CPU and I/O time. If you log too little, you won't have enough information to diagnose problems. And no matter how efficiently you implement your logging, if you don't check your logs you won't know when bad things are happening.

So here's a Log4j appender that sends emails for messages logged at the Error level or higher. Yes, Log4j comes with an appender that sends emails, org.apache.log4j.net.SMTPAppender. The one I present here is a little simpler, but more importantly it's Grails-friendly. Specifically it doesn't send emails unless the app is running in production mode. Error emails are great, but very annoying while debugging

Unfortunately since this class will be compiled with the application code after Config.groovy is loaded, you can't add it to the Config.groovy log4j section. Instead, just put some initialization code in Bootstrap:

Also, note that I've omitted the setter and declaration of 'mailService', which you'll need to provide. The Grails mail plugin is good candidate. The details of what the email body looks like and who receives the emails is left as an exercise for the reader.

As I said, this is different from the standard email appender, so use that one if you prefer, but either way you should be using something to automatically notify yourself when errors are happening.

One consideration that's important when implementing this is clarifying what you consider an Error-level or Fatal message. Ideally a Fatal error message should be severe enough that pagers start going off and phones start ringing (that'll take another appender). So it's important to decide what gets logged and at what level, so you don't overwhelm yourself and support people with so many non-critical messages that they start ignoring them.

I've browsed through the Log4j source code several times when I needed to write a custom appender, debug some obscure logging issues, etc., and I'd seen the variables FQCN and callerFQCN but never really needed to know what those were until this week.

I had gotten frustrated with this bloated (but necessary) pattern in a lot of our code:

The isDebugEnabled() check is necessary since foo and bar might have large and/or expensive toString() realizations, and if the Debug level isn't enabled, the string concatenation will have been wasted, a potentially significant performance problem.

So we do a lightweight check to see if it's even necessary to build up the string; the unfortunate part is that it takes 3 lines instead of 1, and if there's a lot of debug logging in a class a significant portion of the code is just logging.

To simply things I borrowed an idea from Seam's logging and wrote a utility class that accepts a logger, a message with {0}, {1}, etc. placeholders in MessageFormat style, and varargs parameters to replace the {0}, {1} placeholders, e.g.

and the Logger class handles the test that the provided log has debug enabled, and uses MessageFormat to build the final message only if necessary.

This worked great and I switched over a lot of verbose logging calls to use the new approach. But a team member complained that he'd turned on class (%C) and method (%M) logging, and it was claiming that the entries were being logged from the utility class Logger and method debug (although the category name was of course correct). I hadn't noticed this since he'd only turned on these expensive extra options to debug some obnoxious bugs currently wreaking havoc on our application.

We're using Commons Logging¹ so I needed to cast the Log instance to a Log4JLogger to access the native Logger via getLogger().

Once I do that, I can convert

to the equivalent but more useful

or more specifically

where the last parameter is the optional Throwable, not relevant to this discussion.

But what's the FQCN? This is a String, "org.apache.log4j.Logger" if you're using Log4j directly. The purpose of this is to be able to find the calling method if necessary. Log4j uses a stack trace from a new Throwable to determine the caller (hence the expense of these logging parameters - they shouldn't be used except for unusual cases).

A stack trace generated in Log4j's code will have some number of stack elements from the Log4j method calls, then the logger call itself, then the application stack elements. So if you know the fully qualified class name of the logger class, then you can find it in the stack trace, go one deeper, and you know the class name, method, and line number (if javac debug is on).

But I'd introduced one more stack element into the trace, defeating the lookup. Luckily for me, all I needed to do was the replacement above, and substitute the full class name of my utility class and the actual calling method is now correctly resolved.

1. One of the first things I wanted to change when I started on the project was to remove Commons Logging and use Log4J directly since it provides no benefit in our application. I should have seen the nonsensical knee-jerk refusal to consider this as an omen of things to come, but I didn't. Oh well, more on that later [back]

Although you can configure Log4j programmatically, it's far more common to put log4j.properties or log4j.xml in your classpath to trigger autoconfiguration. But one problem that I always have is specifying the location of my log files. From what I can tell, these are your options:
(more...)