Posterous theme by Cory Watilo

Filed under: logging

Grails: Replacing log4j with logback

Logging configuration has long been a bit of a pain point for Grails development. We have the log4j configuration DSL, which is intended to simplify logging configuration for those unfamiliar with the powerful log4j logging framework. However, this configuration method falls short on a number of counts:

  • for those already familiar with log4j XML configuration syntax, the log4j DSL is not particularly intuitive
  • moderately complex logging configurations can be a pain to get right – usually this is a process of trial-and-error
  • creating a per-environment configuration isn’t simple
  • when the application is running in the production environment, it’s difficult to re-configure logging at runtime

Some of these problems can be solved by using certain plugins; there is the Log4j XML Plugin, which allows you to use a log4j.xml configuration file, and the Dynamic Logging Plugin, which allows you to modify the logging configuration or a running application.

Another promising solution is to ditch log4j altogether, and switch to it’s “successor”, logback. Logback offers both XML and Groovy configuration options, and as a bonus, can scan the configuration file at runtime for changes.

In theory, the switch to logback should be trivial; Grails uses the SLF4J logging facade under the hood, and logback is a direct implementation of the SLF4J API. You should be able to simply remove the log4j dependency JARs from your $GRAILS_HOME/lib folder, and replace them with their logback equivalents. However, the reality is not quite so simple. Grails seems to be coupled to the log4j API at a couple of points in it’s build and bootstrap phases, and will complain if the log4j classes cannot be found.

Switching out log4j dependencies for logback

After some experimentation, I found a reasonable solution: instead of adding/removing libraries from the $GRAILS_HOME/lib folder, the switch to logback can be achieved almost entirely within the BuildConfig.groovy configuration file. All we need to do is to exclude the slf4j-log4j12 dependency, and add some logback-specific dependencies to the build and runtime phases (see below).

UPDATE: By default, Grails will package lockback-test.xml into the application WAR file. You probably don’t want this, as the setting in logback.xml will be ignored. TO get around this, Grails must be instructed to remove logback-test.xml from the WAR staging dir. See the updated BuildConfig.groovy below for how to do this.

Note that I’m using logback version 0.9.17, not the latest version. This is because 0.9.17 is the latest version supported by the version of SLF4J (1.5.8) which ships with Grails 1.3.7.

Logback configuration

Now that we are using logback instead of log4j, we need to do away with the log4j configuration stanza in Config.groovy, and replace it with a logback.xml configuration. You can put your logback.xml into the grails-app\conf folder; this works fine when your application is executed from a WAR, but there are a couple of gotchas if you use run-app:

  • After creating the logback.xml file, it won’t be picked up the first time you run grails run-app. The first run copies the configuration to the ~/.grails/1.3.7/projects/<project name>/resources/ folder, but too late to be picked up by logback’s configurator. It is picked up from the second run onwards.
  • If you change the logback.xml configuration, you’ll need to run grails clean, then grails run-app twice to get the changes picked up. Frustrating.
  • logback’s scanning and auto re-loading of the config file doesn’t work, unless you make your edits to ~/.grails/1.3.7/projects/<project name>/resources/logback.xml

The solution is to configure your development environment to run grails with the system property logback.configurationFile set to the path of your logback.xml configuration file, e.g. <project root>/grails-app/conf/logback.xml. This will force logback to pick up the configuration from there, instead of the resources folder. Now, you can use logback’s configuration scanning feature to modify your logging configuration while the app is running. Nice!

You can also make use of the logback.configurationFile system property to externalize your logback configuration in your production environment. This allows you to easily re-configure logging on a running instance without having to delve into the exploded WAR folder.

Configuring logback with the Groovy DSL

Disappointingly, I couldn’t get the Groovy configuration to work at all. I tried putting logback.groovy into grails-app/conf, but it didn’t get copied over to the resources folder. I then tried putting it into src/groovy, but it still wasn’t picked up by the logback configurator. The logback.configurationFile system property trick doesn’t work either, because annoyingly logback expects that file to be XML rather than Groovy. If you know of a way to get Groovy configuration working, please share in the comments!

Conclusion

Without the ability to configure logging with Groovy, switching from log4j to logback isn’t as attractive a proposition as it could be. However, even with the XML configuration you still get the other benefits of using logback:

If you’d like the switching of logging frameworks to be simpler in future versions of Grails, please vote on the JIRA issue GRAILS-7588

For reference, here is a simple working logback.xml configuration:

Monitoring a Grails app using Splunk

Grails + Splunk = happy

Splunk is a popular, enterprise-grade tool for IT infrastructure monitoring. If you haven’t come across it before, I’d take 5 minutes to check out this introductory video. In a nutshell, Splunk indexes any form of time-series data, and provides an interface for searching, analysing and reporting on these data.

The enterprise version of Splunk can be used to provide real-time info on all aspects of the operation of entire data clusters, and as you can imagine it has an enterprise-sized price tag to match. However, the good news is that there’s also a version which is free to use if you’re indexing less than 500MB of data a day and don’t require some of the advanced functions such as real-time alerts. This makes Splunk a great tool for small shops and early-stage startups to use for web-app monitoring and performance analysis.

Splunk can consume pretty much any logs your server can produce: syslog, database, Apache, mail, log4j, top – you name it, if it’s a plain-text time-stamped log file, Splunk will index it. However, in this introductory post, I’m going to keep things simple and describe how to get Splunk up and running to provide real-time monitoring of the log4j logs produced by a Grails application.

Splunk is fairly lightweight, so can usually be run on the same server as your Grails app. However, I’m going to take a slightly different approach and run Splunk on my development machine, to avoid having to install any new software on my app server.

First thing is to download and install Splunk. Head over to this page, and choose the appropriate distribution for your machine. Installation is painless and only takes 5 minutes, but if you run into trouble, check out the help pages on the Splunk site. That’s another great thing about Splunk: the documentation is really, really good. Extremely comprehensive and well-written. They even run a Q&A forum using the StackOverflow API.

Once you’re installed, start up Splunk by running

/opt/splunk/bin/splunk start --accept-license

(on Ubuntu/Debian – your system may differ). Load up the web front-end by going to http://localhost:8000/, and log in as admin (password “changeme”).

Okay, now Splunk is up and running we need some data to feed it. The simplest way is to point Splunk at a log file and tell it to tail it. If you’re running Splunk on the same machine as you’re app, this is simple. If not, we need to do an extra step to get the log file onto our development machine. I decided to go with tried-and-trusted cron and rsync:

* * * * * rsync -e ssh -avlq {remote-user}@{remote-host}:{absolute-path-to-remote-log-file} {absolute-path-to-local-log-file} >/dev/null 2>&1

(replace text in curly brackets as appropriate). Thus my application log will be sync’d to my development machine every minute. Remember, this method will only work if you have your development machine registered as an allowed host on your production server.

Now, go to http://localhost:8000/manager/search/data/inputs/monitor and click ‘New’ to add your log file as a new input. Here are the options you want:

  • Source: {absolute-path-to-local-log-file}
  • Host: {remote-host} // but fine to leave as the default
  • Source type: Automatic // Splunk will auto-detect the log4j format
  • Index: default
  • Advanced options: Follow tail: checked

Click ‘Save’, and Splunk will now begin to index the log file, and monitor it for changes.

Now that the set-up is complete, the fun begins. Head over to http://localhost:8000/app/search/dashboard – this is where you can get a visualization of the contents of your log file, filter the contents, search for events, and build reports. The guys at Splunk do a better job of demonstrating these features than I could, so at this point I’ll direct you to one of the many demo videos on the Splunk site. Alternatively, check out the search tutorial in the docs.

Hopefully I’ve showed you how easy it is to set up Splunk and get it analysing the logs of your running Grails app – without having to make a single change to your production server!