Archive for the Category 'log4j'

Using the Log4j MDC in Grails

Friday, January 14th, 2011

I read this interesting blog post about using the Log4j MDC to add information to logged messages that was referenced on the Grails User mailing list and wondered what it would take to get it working in Grails since the example is traditional Java. Turns out it’s pretty simple.


But first – what is the MDC? It’s Log4j’s MDC class, which implements a Mapped Diagnostic Context. There’s a similar class, NDC, which implements a Nested Diagnostic Context. In this case there’s no need for nesting, we just want to store temporary information in thread-local storage under a key, so MDC makes more sense. Click the links to read the Javadoc for the two classes, and see this wiki page for a comparison of the two.

Also note that if there’s an SLF4j wrapper for this class that you can use if you want the logging implementation transparency that SLF4j provides.


Ok, so how would we use this in Grails? There are just two steps:

  • create a filter to store data in the MDC
  • edit the logging pattern to include the data

We have two options for the filter – either a Grails filter, or a servlet filter. Grails filters only apply to controller requests and are written in Groovy, whereas servlet filters apply to whatever request pattern you specify in web.xml and are written in Java or Groovy. So the decision about which to use comes down to what you want to filter, and if you have Groovy/Java performance concerns.

Grails Filter

To use a Grails filter, run the create-filters script, e.g.

grails create-filters com.burtbeckwith.mdctest.logging

and add this code to grails-app/conf/com/burtbeckwith/mdctest/LoggingFilters.groovy:

package com.burtbeckwith.mdctest

import org.apache.log4j.MDC

class LoggingFilters {

   def filters = {
      all(controller:'*', action:'*') {
         before = {
            MDC.put 'username', request.userPrincipal?.name ?: 'N/A'
         }
         afterView = { e ->
            MDC.remove 'username'
         }
      }
   }
}

We're storing the logged-in user's name to the MDC under the username key, or 'N/A' if there's no authenticated user. You can also store other request-specific information, but for this example we'll keep things simple. Also note that after the request is finished processing we remove the data from the MDC to avoid memory leak issues.

Servlet Filter

If you want to use a servlet filter, create a class in src/java, e.g. src/java/com/burtbeckwith/mdctest/MdcFilter.java, and add this code:

package com.burtbeckwith.mdctest;

import java.io.IOException;
import java.security.Principal;

import javax.servlet.Filter;
import javax.servlet.FilterChain;
import javax.servlet.FilterConfig;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.http.HttpServletRequest;

import org.apache.log4j.MDC;

public class MdcFilter implements Filter {

   public void doFilter(ServletRequest req, ServletResponse res, FilterChain fc)
         throws IOException, ServletException {
      try {
         Principal principal =1;
         chain.doFilter(req, res);
      }
      finally {
         MDC.remove("username");
      }
   }

   public void init(FilterConfig fc) {/*nothing to do*/}
   public void destroy() {/*nothing to do*/}
}

You'll need to add this to web.xml, so run

grails install-templates

if you haven't already and add a filter and a filter-mapping element:

<filter>
   <filter-name>com.burtbeckwith.mdctest.MdcFilter</filter-name>
   <filter-class>com.burtbeckwith.mdctest.MdcFilter</filter-class>
</filter>

<filter-mapping>
   <filter-name>com.burtbeckwith.mdctest.MdcFilter</filter-name>
   <url-pattern>/*</url-pattern>
</filter-mapping>

Edit the logging pattern

We need to update the logging pattern to include the MDC data, so add an appender override for the 'console' appender (update your other appenders similarly) in grails-app/conf/Config.groovy:

log4j = {
   appenders {
      console name: 'stdout',
              layout: pattern(conversionPattern: '%c{2} %m - %X{username}%n')
   }
   ...
}

The significant change is the addition of %X{username} to include the username value.

Testing

To test this, I installed the Spring Security plugin and added a test user. I created two simple controllers, one that requires authentication:

import grails.plugins.springsecurity.Secured

@Secured(['ROLE_ADMIN'])
class AdminController {
   def index = {
      log.debug 'accessing admin controller'
      render 'Hello admin'
   }
}

and one that doesn't:

class TestController {
   def index = {
      log.debug 'accessing test controller'
      render 'Hello world'
   }
}

Then I configured controllers to log at the debug level:

log4j = {
   ...
   debug 'grails.app.controller'
   ...
}

and ran the application. Accessing /test shows that I'm not logged in:

mdctest.TestController accessing test controller - N/A

and accessing /admin after logging in displays my username:

mdctest.AdminController accessing admin controller - admin

Download the sample application here.

There's a user 'admin' configured in BootStrap.groovy with password 'password' that you can use to test login.

Note that the sample application has both filters implemented, so you should remove the one you don't want to use.

  1. HttpServletRequest)req).getUserPrincipal(); MDC.put("username", principal == null ? "N/A" : principal.getName([back]

Grails App-Info plugin

Saturday, July 17th, 2010

Update July 5, 2012: See this blog post for an updated test app and support for Grails 2.0+.

I released a new Grails plugin today, app-info. This plugin exposes a lot of internal information for a Grails application. Most of the code for this plugin dates back a long time and was originally mostly JSPs that I would copy into whatever application I was working on to give myself a view into what’s going on. Over time as I started using Spring and Hibernate I added more pages to display that information, and it now also shows information about Grails too.
(more…)

Using GMail with a Log4j SMTP Appender in Grails

Wednesday, February 03rd, 2010

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:

System.setProperty 'mail.smtp.port', '587'
System.setProperty 'mail.smtp.starttls.enable', 'true'

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:

import org.apache.log4j.Level
import org.apache.log4j.net.SMTPAppender

...

mail.error.server = 'smtp.gmail.com'
mail.error.port = 587
mail.error.username = 'your.email@gmail.com'
mail.error.password = 'yourpassword'
mail.error.to = 'to@yourapp.com'
mail.error.from = 'from@yourapp.com'
mail.error.subject = '[Application Error]'
mail.error.starttls = true
mail.error.debug = false

environments {
   production {
      grails.serverURL = "http://www.changeme.com"
   }
   development {
      grails.serverURL = "http://localhost:8080/${appName}"
   }
   test {
      grails.serverURL = "http://localhost:8080/${appName}"
   }
}

log4j = {

   System.setProperty 'mail.smtp.port', mail.error.port.toString()
   System.setProperty 'mail.smtp.starttls.enable', mail.error.starttls.toString()

   appenders {

      appender new SMTPAppender(name: 'smtp', to: mail.error.to, from: mail.error.from,
         subject: mail.error.subject, threshold: Level.ERROR,
         SMTPHost: mail.error.server, SMTPUsername: mail.error.username,
         SMTPDebug: mail.error.debug.toString(), SMTPPassword: mail.error.password,
         layout: pattern(conversionPattern:
            '%d{[ dd.MM.yyyy HH:mm:ss.SSS]} [%t] %n%-5p %n%c %n%C %n %x %n %m%n'))
   }

   error  'org.codehaus.groovy.grails.web.servlet',  //  controllers
          'org.codehaus.groovy.grails.web.pages', //  GSP
          'org.codehaus.groovy.grails.web.sitemesh', //  layouts
          'org.codehaus.groovy.grails.web.mapping.filter', // URL mapping
          'org.codehaus.groovy.grails.web.mapping', // URL mapping
          'org.codehaus.groovy.grails.commons', // core / classloading
          'org.codehaus.groovy.grails.plugins', // plugins
          'org.codehaus.groovy.grails.orm.hibernate', // hibernate integration
          'org.springframework',
          'org.hibernate',
          'net.sf.ehcache.hibernate'
   warn   'org.mortbay.log'

   root {
      error 'stdout', 'smtp'
      additivity = true
   }
}

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.

Performance issues with GString logging

Sunday, December 28th, 2008

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:

log.debug("foo is " + foo);

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:

if (log.isDebugEnabled()) {
   log.debug("foo is " + foo);
}

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;

log.debug("just a simple string");

incurs next to zero overhead.


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

log.debug "foo is ${foo}"

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():

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

class Thing {
  String toString() {
    println "calling thing tostring"
    return "a thing"
  }
}

def thing = new Thing()

def log = Logger.getLogger('foo')
log.level = Level.INFO
log.debug "Debug: Thing: $thing"
log.error "Error: Thing: $thing"

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.

A Grails-aware Log4j SMTP Appender

Wednesday, September 10th, 2008

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 🙂

import grails.util.GrailsUtil;

import org.apache.log4j.AppenderSkeleton;
import org.apache.log4j.Level;
import org.apache.log4j.Logger;
import org.apache.log4j.PatternLayout;
import org.apache.log4j.spi.LoggingEvent;
import org.codehaus.groovy.grails.commons.GrailsApplication;

/**
 * Replacement for Log4j's SMTP appender that uses the mail service.
 *
 * @author Burt
 */
public class SmtpErrorAppender extends AppenderSkeleton {

  /**
   * Perform 1-time initialization.
   */
  public static void register() {
    if (!GrailsApplication.ENV_PRODUCTION.equals(GrailsUtil.getEnvironment())) {
      // only configure for production
      return;
    }

    SmtpErrorAppender appender = new SmtpErrorAppender();
    Logger.getRootLogger().addAppender(appender);
    Logger.getLogger("StackTrace").addAppender(appender);
  }

  /**
   * Constructor with default values.
   */
  public SmtpErrorAppender() {
    setThreshold(Level.ERROR);
    setLayout(new PatternLayout(
      "%-27d{dd/MMM/yyyy HH:mm:ss Z}%n%n%-5p%n%n%c%n%n%m%n%n"));
  }

  /**
   * {@inheritDoc}
   */
  @Override
  public void append(final LoggingEvent event) {

    if (!event.getLevel().isGreaterOrEqual(Level.ERROR)) {
      return;
    }

    event.getThreadName();
    event.getNDC();
    event.getMDCCopy();

    mailService.sendErrorEmail(layout.format(event), event);
  }

  /**
   * {@inheritDoc}
   * @see org.apache.log4j.AppenderSkeleton#close()
   */
  public synchronized void close() {
    closed = true;
  }

  /**
   * {@inheritDoc}
   * @see org.apache.log4j.AppenderSkeleton#requiresLayout()
   */
  public boolean requiresLayout() {
    return true;
  }
}

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:

class BootStrap {

  def init = { servletContext ->
    // can't put this in Config.groovy since the class won't have been compiled yet
    SmtpErrorAppender.register()
  }
}

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.

WTF is Log4j’s FQCN?

Monday, August 13th, 2007

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:

if (log.isDebugEnabled()) {
   log.debug("foo=" + foo + ", bar=" + bar);
}

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.

Logger.debug(log, "foo={0}, bar={1}", foo, bar);

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 Logging1 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

log.debug(message);

to the equivalent but more useful

((Log4JLogger)log).getLogger().log(Level.DEBUG, message);

or more specifically

((Log4JLogger)log).getLogger().log(FQCN, Level.DEBUG, message, null);

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]

Where Are Your Log4j Log Files?

Monday, August 28th, 2006

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…)

Creative Commons License
This work is licensed under a Creative Commons Attribution 3.0 License.