Logging different log levels to different appenders with logback

Assume a scenario where you want debug messages to be logged a different file than the main one that captures messages above info log level. The way to configure this is quite different especially when you come from a log4j background.

Email Alerts With Logback

Logback provides a support to send logged messages in an email through an SMTPAppender. The SMTPAppender accumulates logging events in one or more fixed-size buffers and sends the contents of the appropriate buffer in an email after a user-specified event occurs. By default, the email transmission is triggered by a logging event of level ERROR or higher. Moreover, by default, a single buffer is used for all events.

A sample smtp appender configuration would look like below

Advertisement

Enabling Logback JMX MBean In Glassfish

Logback support for JMX can be enabled by just adding a <jmxconfigurator/> tag in the configuration file but this is not how a web application should register the logback MBean if you web application is deployed in a glassfish application server. If you do it you would get the below error message on accessing the logback MBean through JConsole –

“Problem invoking getLoggerLevel : java.lang.IllegalStateException: WEB9031: WebappClassLoader unable to load resource[java.lang.Object], because it has not been started or was always stopped”

The root cause is an integration issue between logback and glassfish. On startup glassfish instantiates two classloaders for each of the deployed web application. The first one is a temporary one which is later destroyed.

When your web-application classes get loaded with this temporary classloader, logback initialization gets triggered (if the Logger instances are declared as static instances in your application classes which is mostly the case) like I explain in my older post. During this initialization process logback creates a JMX MBean instance (JMXConfigurator.class) and registers it with the MBean server. At certain point glassfish destroys the temporary classloader and nullifies all the static or final fields from the loaded classes. At a later step a new classloader is instantiated which would be the actual classloader for the web application. This classloader starts & loads the web context and the deployment continues.

The above mentioned error is displayed because while nullifying the classes during the destroy step of the temporary classloader, the registered MBean is not unregistered and logback does not re-register the MBean during the logback initialization step (which is triggered after the actual class loader is instantiated) since a MBean with that name was already registered. Here is short snippet of code from the JMXConfiguratorAction class which does the MBean registration.

    MBeanServer mbs = ManagementFactory.getPlatformMBeanServer();
    if(!MBeanUtil.isRegistered(mbs, objectName)) {
      // register only of the named JMXConfigurator has not been previously
      // registered. Unregistering an MBean within invocation of itself
      // caused jconsole to throw an NPE. (This occurs when the reload* method
      // unregisters the
      JMXConfigurator jmxConfigurator = new JMXConfigurator((LoggerContext) context, mbs,
          objectName);
      try {
        mbs.registerMBean(jmxConfigurator, objectName);
      } catch (Exception e) {
        addError("Failed to create mbean", e);
      }
     }

A mystery would be to understand the reason behind glassfish creating a temporary classloader(It is hard to figure it out exactly from the source code 🙂 ).
One simple workaround that can be implemented to resolve this issue is not add the <jmxConfigurator/> tag in the logback configuration file and to manually register the logback jmx mbean in a servlet context listener. Have a look at JMXConfiguratorAction.class for more details on how to register the logback MBean.

This note could be a good addition to the well documented Logback manual :).

Log to same file from multiple jvms using logback

Logback includes a feature which allows multiple jvms potentially running on different hosts to log to the same log file. This feature can be enabled by setting “prudent” property of an FileAppender to true.

<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
         <!-- Support multiple-JVM writing to the same log file -->
         <prudent>true</prudent>
</appender>

Note – RollingFileAppender extends FileAppender with the capability to rollover log files.

This feature is implemented using the file locking API introduced in JDK 1.4.  The two threads that contend for the same file may be in different JVMs, or one may be a Java thread and the other some native thread in the operating system. The file locks are visible to other operating system processes because Java file locking maps directly to the native operating system locking facility.
A small code snippet from the FileAppender class implementing the prudent feature from logback looks like

public class FileAppender extends OutputStreamAppender {

@Override
protected void writeOut(E event) throws IOException {
      if (prudent) {
         safeWrite(event);
      } else {
         super.writeOut(event);
      }
}

final private void safeWrite(E event) throws IOException {
     ResilientFileOutputStream resilientFOS =
             (ResilientFileOutputStream) getOutputStream();
     FileChannel fileChannel = resilientFOS.getChannel();
     if (fileChannel == null) {
        return;
     }
     FileLock fileLock = null;
     try {
       fileLock = fileChannel.lock();
       long position = fileChannel.position();
       long size = fileChannel.size();
       if (size != position) {
         fileChannel.position(size);
       }
       super.writeOut(event);
     } finally {
       if (fileLock != null) {
         fileLock.release();
     }
}

}

Using Logback in Glassfish v3 – Part II

In my previous post I listed out ways to configure logback in glassfish v3. After researching out and understanding logback more I realized that there is a simpler way.

Logback searches for the logback configuration file (first logback.groovy then logback-test.xml and then logback.xml if the former one is not found) in the classpath. Hence one can just place the logback.xml in the deployed application war and that’s it.  No jvm-option called -Dlogback.configurationFile is needed.

If there is no logback.xml found in the classpath, logback configures itself using BasicConfigurator which will cause the logging output to be directed to the console.  The minimal configuration involves a consoleAppender attached to the root logger which has a default log level of DEBUG.  In glassfish v3, anything logged to the Console i.e. System.out or System.error is sent to the log file via a logger named “javax.enterprise.system.std.com.sun.enterprise.v3.services.impl”. A message to System.err is logged at Level.SEVERE. A message to System.out is logged at Level.INFO.
See the last logger in the below image.

Using Logback in Glassfish v3

The article provides details on how to integrate custom logging framework like slf4j and logback in glassfish v3.  The steps required to achieve this are

1. Add a jvm option
-Dlogback.configurationFile=${com.sun.aas.instanceRoot}/config/logback.xml
from the admin console i.e. server-config -> JVM Settings -> JVM Options

2. Place your logback.xml file under <domain-directory>/config.

The logs would be created relative to <domain-directory>/config.