Previous: Appendix D Up: Part III Next: Appendix F

E Logging in Lift

Logging is a useful part of any application, Lift app or otherwise. Logging can be used to audit user actions, give insight into runtime performance and operation, and even to troubleshoot and debug issues. Lift comes with a thin logging facade that sits on top of the SLF4J library [M] [M] http://www.slf4j.org/. This facade provides simple access to most common logging functions and aims to be easy to use, flexible, and most important, inconspicuous. If you do decide that Lift’s logging facilities don’t meet your needs, it’s possible to use any Java logging framework you desire, but it’s still useful to understand Lift’s framework since Lift uses it internally for logging.

E.1 Logging Backend

The detailed configuration of SLF4J is outside the scope of this book, but we would like to highlight a few key notes concerning SLF4J. First, SLF4J splits the API from the implementation into separate JAR files. This allows you to choose the backing implementation that best suits your deployment. For example, SLF4J contains implementations for JDK logging, log4j, and more. For example, the JBoss application server version 5 and newer comes bundled with its own implementation of the SLF4J API, so you can simply deploy a Lift WAR on JBoss and use the server’s configuration and logging. Similarly, Jetty comes bundled with the SLF4J API.

Outside of container-provided implementations, the logback logging framework [N] [N] http://logback.qos.ch/ is a very nice implementation of the SLF4J API. It’s written by the same people who wrote log4j and has much improved performance and functionality over log4j [O] [O] http://logback.qos.ch/reasonsToSwitch.html. Because logback-classic implements the SLF4J API, you simply need to drop the logback-classic jar into your classpath, or add it as a dependency in your WAR to use it. One particularly nice feature of logback is that if it can’t locate a configuration file (which can be written in XML, Groovy, or soon, Scala), it will default to logging everything to the console.

E.2 Basic Logging

Logging in Lift is performed via the net.liftweb.common.Logger object and trait. The Logger object provides a set of utility methods for configuration and instantiation of logger instances. The Logger trait can be mixed into your snippet, comet, or other classes to provide direct methods for logging (we’ll cover these in Section E.2.3↓).

E.2.1 Logging Setup

The first step in utilizing Lift’s logging is to configure the logger. As we mentioned in Section E.1↑, Lift uses the SLF4J framework. The configuration of SLF4J depends on which backing implementation you use, but Lift comes with helpers for both log4j (net.liftweb.common.Log4j) and for logback (net.liftweb.common.Logback). These helpers are utilized with the Logger object’s setup var. The Log4j helpers provides methods that can be used to load a configuration from a String, a file (either XML or properties), or with Lift’s default (console) logging. The Logback helper provides a single method to load a configuration from an XML file. Listing E.2.1↓ shows how you could use the Logback helper in the Boot.boot method to configure logging from the logconfig.xml file.

Configuring Logback via Logger.setup

def boot {
  // Get a reference to the config from our classpath
  val logUrl = LiftRules.getResource("logconfig.xml")
  
  // Apply the reference, if found
  logUrl.foreach { Logger.setup = Logback.withFile(_) }
  ...
}

E.2.2 Obtaining a Logger

There are two basic means of obtaining a logger instance. The first is to mix the Logger trait into your class. The second is to instantiate a logger using the Logger object’s apply methods.

Mixing the Logger trait into your class is a very simple way to add logging methods in your code, as shown in Listing. When you do this, the underlying logger will have a name derived from your class’s dynamic type. For example, Listing E.2.2↓ shows the definition of our Accounts snippet object with a Logger trait mixed in. When we log in the Accounts object the name will be the fully-qualified classname, or “com.pocketchangeapp.snippet.Accounts” in our case. When you mix the Logger trait into your class, you can access the logging methods (Section E.2.3↓) directly.

Mixing Logger into a Class

object Accounts extends DispatchSnippet with Logger {
  ...
  warn("This is a warning")

The second basic way to obtain a logger instance is to construct one directly via the Logger object’s apply method, as shown in Listing E.2.2↓. The apply method takes either a String or Class that will be used to determine the constructed logger’s name. In our example, we use the classOf[Boot], so our logger will be named “bootstrap.liftweb.Boot”. When you obtain a logger via construction you need to access the logging methods via the logger instance.

Constructing a Logger instance

class Boot {
  // Set up a logger to use for startup messages
  val logger = Logger(classOf[Boot])
  ...
  logger.warn("This is a warning")

There is a third, hybrid, approach to obtaining a Logger that allows you to mix in the Logger trait while controlling the logger name. Listing E.2.2↓ shows how we can mix in th trait and then override the underlying SLF4J logger with our own named instance.

Mixing in a named Logger

class AddEntry extends StatefulSnippet with Logger {
  // Use a different name for our logger
  import org.slf4j.LoggerFactory
  override val _logger = LoggerFactory.getLogger("EntryEdit")

E.2.3 Logging Methods

The Logger trait provides some basic log methods which we’ll summarize here. Each log method comes in three forms: one with just a ⇒ Object argument, one with a ⇒ Object and Throwable argument, and one with a ⇒ Object, Throwable, and Marker argument. These correspond roughly to the SLF4J log methods, although the order of the parameters is different and the parameters are passed by-name. Pass-by-name arguments are used so that computation of the log message can be deferred. This is useful to avoid processing messages for log statements below the current logging threshold, a topic we’ll cover more in Section E.3↓.

trace This logs a message at trace level. Trace level is generally intended for very detailed “tracing” of processing, even more detailed than debug level.

debug Logs a message at debug level. This level is usually used to output internal variable values or other information that is useful in debugging and troubleshooting an app.

info Logs a message at info level. This level is appropriate for general information about the app.

warn Logs a message at warning level. This level should be used for reporting issues that are in error but can be handled cleanly, such as someone trying to submit a character string for a numeric field value.

error Logs a message at error level. This level should be used for messages relating to errors that can’t be handled cleanly, such as a failure to connect to a backing database.

assertLog This allows you to test an assertion condition and if true, logs the assertion as well as a given message.

Listing E.2.3↓ shows our REST API authentication hook, which uses a few different Logging methods within the handler method.

Some example logging

LiftRules.authentication = HttpBasicAuthentication("PocketChange") {
  case (userEmail, userPass, _) => {
    logger.debug("Authenticating: " + userEmail)
    User.find(By(User.email, userEmail)).map { user =>
      if (user.password.match_?(userPass)) {
        logger.info("Auth succeeded for " + userEmail)
        User.logUserIn(user)

        // Set an MDC for logging purposes
        MDC.put("user", user.shortName)

        // Compute all of the user roles
        userRoles(user.editable.map(acct => AuthRole("editAcct:" + acct.id)) ++
                  user.allAccounts.map(acct => AuthRole("viewAcct:" + acct.id)))
        true
      } else {
        logger.warn("Auth failed for " + userEmail)
        false
      }
    } openOr false
  }
}

E.3 Log Level Guards

We want to provide a brief discussion on the use of log guards and why they’re usually not needed with Lift’s log framework. A log guard is a simple test to see if a given log statement will actually be processed. The Log object provides a test method (returning a boolean) for each log level:

isDebugEnabled
isErrorEnabled
isInfoEnabled
isTraceEnabled
isWarnEnabled

Log guards are fairly common in logging frameworks to avoid expensive computation of log message that won’t actually be used. This is particularly relevant with debug logging, since they often cover a large section of code and usually aren’t enabled in production. The Log object can implicitly do log guards for you because of the pass-by-name message parameters. As we showed in listing E.2.3↑, simply converting your log message into a closure allows the Log object decide whether to execute the closure based on the current log level. You get the flexibility and simplicity of adding log statements anywhere you want without explicit log guards, without losing the performance benefit of the guards. To explain it a bit more, let’s assume for instace that the debug method would have been declared as def debug(msg:AnyRef): Unit. When debug would be called the parameter will be first evaluated and then passed to the method. Inside the method we have the test to see if the debug level is enabled to know if we actaully need to trace that message or not. Well in this case even if the debugging level is turned off we still have the evaluation of the parameters and that leads to unnecessary computing and in an application that uses logging heavily that would likely lead to a performance impact.

E.4 Logging Mapper Queries

If you want to log Mapper query activity, there are two main approaches. The first is to utilize the net.liftweb.mapper.DB.addLogFunc method to add your own logging function. A logging function is of the type (DBLog, Long) ⇒ Any. The DBLog trait contains two separate lists of log entries, one for meta operations (such as getFetchSize) and one for actual work statements (such as executeQuery). You can access these two log lists via either the metaEntries or statementEntries methods. You can also access the entire list of both types via the allEntries method. Listing E.4↓ shows how we can hook a log function in the Boot.boot method to log Mapper activity for each request.

Basic Mapper Logging

// Add a query logger
DB.addLogFunc {
  case (log, duration) => {
    logger.debug("Total query time : %d ms".format(duration))
    log.allEntries.foreach {
      case DBLogEntry(stmt,duration) =>
        logger.debug("  %s in %d ms".format(stmt, duration))
    }
  }
}

Another approach to logging Mapper queries is to use the DB.queryCollector logging function and then either use S.queryLog to access the query log, or hook into S.addAnalyzer. Listing E.4↓ shows how we could use this instead for our logging in Boot.boot.

Mapper Logging via S.queryLog

// Add a query logger (via S.queryLog)
DB.addLogFunc(DB.queryCollector)

S.addAnalyzer {
  case (Full(req), duration, log) => {
    logger.debug(("Total request time on %s: %d ms").format(req.uri, duration))
    log.foreach {
      case (stmt,duration) =>
        logger.debug("  %s in %d ms".format(stmt, duration))
    }
  }
  case _ => // we don’t log for non-requests
}

Note that the duration you get when your analyzer function is called is the time spent in S, not necessarily the total duration of your queries. Also, only work statements are logged via S.queryLog. If you want meta entries you’ll have to use a direct logging function as in Listing E.4↑.

Previous: Appendix D Up: Part III Next: Appendix F