Some tips for application logging in Java

Some tips for application logging in Java

In this blog post I want to share some of my thoughts about application logging in Java. Hopefully, you'd find them useful!

1. Consistent use of logging levels

Have a good understanding of the available log levels, and make sure you use them consistently throughout the application. Especially, if you're using the old JDK 1.4 Logger framework. What is the difference between FINER and FINEST?

Below is an abstract list of common log levels and a description of when to use them. This list is based on the Log4J log levels, but can be mapped to other logging frameworks.

FATAL
Unrecoverable errors. Leads to termination of the process (or a crash). Example: the application is in a corrupt state, and has no clue how to restore state.

ERROR
Errors that are not recoverable, but application can continue running. Example: an user request could not be executed, because some inputs are missing or invalid.

WARN
Undesirable or unexpected situations, but not necessarily "wrong". Example: the application expects a value in the cache, but could not find it. The application attempts to get the value in another way. Or a network connection is broken. The application tries to recover by reconnecting.

INFO
Important but normal run time events useful for monitoring. Example: a business process is finished.

DEBUG
Detailed information useful for debugging the system. Example: the content of a variable is printed in strategic locations of the application.

TRACE
Detailed control flow information. Example: a method is called message.

Below is a mapping of log levels of different logging frameworks. Levels that have the same level of severities are placed on the same row.

Carbon Severity Enum	Commons Log	Log4J	JDK 1.4 Logger	LogKit
FATAL	FATAL	FATAL	SEVERE	FATAL_ERROR
ERROR	ERROR	ERROR	SEVERE	ERROR
WARN	WARN	WARN	WARNING	WARN
INFO	INFO	INFO	INFO	INFO
DEBUG	DEBUG	DEBUG	FINE	DEBUG
DEBUG	DEBUG	DEBUG	FINER	DEBUG
TRACE	TRACE	DEBUG	FINEST	DEBUG

2. Proper error logging

Error logging should not be done at the location where an exception is thrown, but at the location where the exception is handled to prevent double logging.

public void doSomething() throws ACheckedException {
 if (someErrorCondition) {
     String errorMessage = "Hey, some error occurred.";
     logger.error(errorMessage);
     throw new ACheckedException(errorMessage);
 }
}

public void callerMethod() {
    try {
     doSomething();
    } catch (ACheckedException exception) {
        logger.error(exception.getMessage());
        doSomethingElse();
    }
}

The code above will log the same error twice. The log statement in the first method can be removed. Exceptions should "bubble up" to the method of the class that can handle the error, and then be logged. In most cases this class will play the controller role in a MVC style application.

3. Prevent unnecessary string concatenations

SLF4J is considered by many the best Java application logging framework. It's a logging facade that masks existing logging frameworks, which can be determined at deployment time. A great feature is that SLF4J allows you to avoid unnecessary string concatenation, which is really expensive.

    logger.error("The error '" + errorMessage +
                 "' occurred in the " +
                 component.getName() + " component.");

Of course, you can use logging guards like this:

    if (logger.isEnabledFor(Level.ERROR) {
        logger.error("The error '" + errorMessage +
                     "' occurred in the " +
                     component.getName() + " component.");
    }

But this will clutter your code, and degrades code readability.

The SLF4J way looks like this:

    log.error("The error '{}' occurred in the {} component.",
              errorMessage, component.getName());

As you can see, the use of SLF4J makes the logging statement more readable, and SLF4J will not compile the log message when the message will not be logged (i.e. not running in a high enough log level).

4. Use complete logging messages

Read logs, and check that the information in the log messages is complete, and can be used to reverse engineer back to the original state of the system.

01/02/2011 ERROR The user has a missing property.

The log message above could be improved by adding: the identifier for the user, and the name of the property, so it's easier to understand (and recreate) the situation that caused the log message. Another improvement is to add a message that gives information about what will happen next.

If you also have tips or views about application logging in Java, please don't hesitate to share them in the comments!

Restarting a Java application programmatically

I found an interesting article through DZone (excellent site) about how to start a Java application programmatically. The original article can be found on the blog of Leo Lewis. Restarting a Java application is pretty useful for certain applications, where you don't have direct access to the deployment environment.

Here is the orginal link to the article:
http://leolewis.website.org/wordpress/?p=499

JAR-files and Property-files in an EAR-file

If you get a ClassNotFoundException when deploying an EAR-file, chances are that shared library/utility JAR-files like hibernate3.jar or log4j.jar are not included in the EAR-file.

Place the missing files directly in APP-INF/lib of the EAR-file. Property-files must be placed in APP-INF/classes. This ensures both types of files are visible after deployment.

More on this subject can be found here.

Configuring your Java web application as root (/)

By default, if you deploy an application "myWebApp" in an application server like Glassfish, the root URL is http://my.server.com:8080/myWebApp. To change this, you can use the sun-web.xml descriptor file of the application to configure the application as root application of the server. Which means that the application is accessible using the URL http://my.server.com:8080/.

Inside the sun-web.xml file, make sure the context-root element looks like this:

<context-root>/</context-root>

The document type definition (DTD) of the descriptor file can be found here.

If the web application is part of an EAR-file, make sure you configure this in application.xml. Otherwise, the setting in application.xml will override it!

To make the URL even simpler, you can ofcourse change the listen port to 80. The URL to the application will then look like this: http://my.server.com/

Using Oracle WebLogic deployment plans

As a developer, I often develop applications that have to be deployed and run in different execution environments. Initially, I start out developing for a development environment. Application tests are executed on a testing environment. The end-users can test and accept the system in the acceptance environment. The final environment is the production environment, where the application is actually used by end-users. This software development cycle is called a DTAP-street.

This has consequences on the Java development, configuration, and deployment process. On every execution environment, there are: different systems we have to connect to, different database/JDBC names we have to use, different IP-addresses/ports we can use, etcetera. This affects the way we package our application (WAR, JAR, and EAR). We want to avoid changing code or annotations for every execution environment. This way we don't need a specific tailor made package for every execution environment.

This blogpost is about how to deal with environment dependent parameters like: IP-addresses and JDBC-names. when you use Oracle WebLogic as your application server. We put these parameters in the deployment plan. For every execution environment, we create a specific deployment plan for it. The parameters in the deployment plan will override the default parameters in the application when deployed. This enables us to use the same application package (WAR, JAR, and EAR) for all the different execution environments.

An example application EAR file is created in this blogpost to illustrate the use of a deployment plan. It consists of the following steps:

1. Create an EJB project, a web project, and an EAR project that contains the first two projects
   
2. Use JNDI lookup and resource injection to read out or inject environment parameters from deployment descriptors
   
3. Create an Oracle WebLogic deployment plan to override the parameters in the standard deployment descriptors
   

First, we create an EJB project with the following stateless session bean:

package com.javaeenotes;

import javax.annotation.Resource;
import javax.ejb.Stateless;

@Stateless(mappedName = "ejb/ejbEnv")
public class EjbEnv implements EjbEnvRemote, EjbEnvLocal {
  @Resource
  private String var1;
  
  @Resource
  private int var2;

  public String getVar1() {
    return var1;
  }

  public int getVar2() {
    return var2;
  }
}

Make sure you also implement the local and remote interfaces to expose the "getter" methods. We have two @Resource annotations to mark the variables we are going to inject with parameters in the ejb-jar.xml deployment descriptor.

Now, create the ejb-jar.xml deployment descriptor:

<?xml version="1.0" encoding="UTF-8"?>
<ejb-jar xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
 xmlns="http://java.sun.com/xml/ns/javaee"
 xmlns:ejb="http://java.sun.com/xml/ns/javaee/ejb-jar_3_0.xsd"
 xsi:schemaLocation="http://java.sun.com/xml/ns/javaee
 http://java.sun.com/xml/ns/javaee/ejb-jar_3_0.xsd"
 version="3.0">

  <display-name>env_ejb</display-name>
  <enterprise-beans>
    <session>
      <ejb-name>EjbEnv</ejb-name>

      <env-entry>
        <env-entry-name>
          com.javaeenotes.EjbEnv/var1
        </env-entry-name>
        <env-entry-type>
          java.lang.String
        </env-entry-type>
        <env-entry-value>
          Environment variables from ejb-jar.xml
        </env-entry-value>
      </env-entry>

      <env-entry>
        <env-entry-name>
          com.javaeenotes.EjbEnv/var2
        </env-entry-name>
        <env-entry-type>
          java.lang.Integer
        </env-entry-type>
        <env-entry-value>
          999
        </env-entry-value>
      </env-entry>

    </session>
  </enterprise-beans>
</ejb-jar>

When the stateless session bean is loaded, both parameters will be injected into the attributes of the bean. Notice that we don't need "setter" methods to do this.

Next, create a web project with a simple servlet:

package com.javaeenotes;

import java.io.IOException;

import javax.ejb.EJB;
import javax.naming.Context;
import javax.naming.InitialContext;
import javax.naming.NamingException;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServlet;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

public class WebEnv extends HttpServlet {
  @EJB(name="ejb/ejbEnv")
  private EjbEnvRemote ejbEnv;

  protected void doGet(HttpServletRequest request,
                       HttpServletResponse response)
      throws ServletException, IOException {

    try {
      Context env = (Context) new InitialContext()
        .lookup("java:comp/env");

      String s = (String) env.lookup("webVar1");
      int i = ((Integer) env.lookup("webVar2")).intValue();

      response.getWriter().write(
        "webVar1: " + s + "\n");
      response.getWriter().write(
        "webVar2: " + i + "\n");

      response.getWriter().write(
        "ejbVar1: " + ejbEnv.getVar1() + "\n");
      response.getWriter().write(
        "ejbVar2: " + ejbEnv.getVar2() + "\n");
    } catch (NamingException e) {
      response.getWriter().write("NamingException");
    }
  }
}

This servlet uses JNDI-lookup to read parameters defined in the web.xml deployment descriptor. You can also see that the stateless session bean we created earlier is injected as attribute when this class is instantiated. When this servlet is called, it will print the environment parameters defined in both the ejb-jar.xml and web.xml.

The web.xml deployment descriptor looks like this:

<?xml version="1.0" encoding="UTF-8"?>
<web-app xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
 xmlns="http://java.sun.com/xml/ns/javaee"
 xmlns:web="http://java.sun.com/xml/ns/javaee/web-app_2_5.xsd"
 xsi:schemaLocation="http://java.sun.com/xml/ns/javaee
 http://java.sun.com/xml/ns/javaee/web-app_2_5.xsd"
 id="env_web" version="2.5">

  <display-name>env_web</display-name>

  <servlet>
    <description></description>
    <display-name>WebEnv</display-name>
    <servlet-name>WebEnv</servlet-name>
    <servlet-class>com.javaeenotes.WebEnv</servlet-class>
  </servlet>

  <servlet-mapping>
    <servlet-name>WebEnv</servlet-name>
    <url-pattern>/WebEnv</url-pattern>
  </servlet-mapping>

  <env-entry>
    <env-entry-name>webVar1</env-entry-name>
    <env-entry-type>java.lang.String</env-entry-type>
    <env-entry-value>
      Environment variables from web.xml
    </env-entry-value>
  </env-entry>

  <env-entry>
    <env-entry-name>webVar2</env-entry-name>
    <env-entry-type>java.lang.Integer</env-entry-type>
    <env-entry-value>888</env-entry-value>
  </env-entry>
</web-app>

Finally, package both projects in an EAR file, and deploy it on the Oracle WebLogic application server. Use the browser to view the output of the servlet. It will print:

webVar1: Environment variables from web.xml
webVar2: 888
ejbVar1: Environment variables from ejb-jar.xml
ejbVar2: 999

Viewing the output, we can verify that it works!

The last step is to create a deployment plan "Plan.xml", which we use to override the parameters defined in both deployment descriptors. The example contents of the deployment plan:

<?xml version='1.0' encoding='UTF-8'?>
<deployment-plan xmlns="http://xmlns.oracle.com/weblogic/deployment-plan"
 xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
 xsi:schemaLocation=
 "http://xmlns.oracle.com/weblogic/deployment-plan
 http://xmlns.oracle.com/weblogic/deployment-plan/1.0/deployment-plan.xsd"
 global-variables="false">
 <application-name>env_ear</application-name>

 <variable-definition>
  <variable>
   <name>WebEnv_Var1</name>
   <value>NEW environment variables from web.xml</value>
  </variable>
  <variable>
   <name>WebEnv_Var2</name>
   <value>800</value>
  </variable>
  <variable>
   <name>EjbEnv_Var1</name>
   <value>NEW environment variables from ejb-jar.xml</value>
  </variable>
  <variable>
   <name>EjbEnv_Var2</name>
   <value>900</value>
  </variable>
 </variable-definition>

 <module-override>
  <module-name>env_ear.ear</module-name>
  <module-type>ear</module-type>
  <module-descriptor external="false">
   <root-element>weblogic-application</root-element>
   <uri>META-INF/weblogic-application.xml</uri>
  </module-descriptor>
  <module-descriptor external="false">
   <root-element>application</root-element>
   <uri>META-INF/application.xml</uri>
  </module-descriptor>
  <module-descriptor external="true">
   <root-element>wldf-resource</root-element>
   <uri>META-INF/weblogic-diagnostics.xml</uri>
  </module-descriptor>
 </module-override>
 <module-override>
  <module-name>env_ejb.jar</module-name>
  <module-type>ejb</module-type>
  <module-descriptor external="false">
   <root-element>weblogic-ejb-jar</root-element>
   <uri>META-INF/weblogic-ejb-jar.xml</uri>
  </module-descriptor>
  <module-descriptor external="false">
   <root-element>ejb-jar</root-element>
   <uri>META-INF/ejb-jar.xml</uri>

   <variable-assignment>
    <name>EjbEnv_Var1</name>
    <xpath>/ejb-jar/enterprise-beans/session/
    [ejb-name="EjbEnv"]/env-entry/
    [env-entry-name="com.javaeenotes.EjbEnv/var1"]/
    env-entry-value</xpath>
    <operation>replace</operation>
   </variable-assignment>

   <variable-assignment>
    <name>EjbEnv_Var2</name>
    <xpath>/ejb-jar/enterprise-beans/session/
    [ejb-name="EjbEnv"]/env-entry/
    [env-entry-name="com.javaeenotes.EjbEnv/var2"]/
    env-entry-value</xpath>
    <operation>replace</operation>
   </variable-assignment>

  </module-descriptor>
 </module-override>
 <module-override>
  <module-name>env_web.war</module-name>
  <module-type>war</module-type>
  <module-descriptor external="false">
   <root-element>weblogic-web-app</root-element>
   <uri>WEB-INF/weblogic.xml</uri>
  </module-descriptor>
  <module-descriptor external="false">
   <root-element>web-app</root-element>
   <uri>WEB-INF/web.xml</uri>

   <variable-assignment>
    <name>WebEnv_Var1</name>
    <xpath>/web-app/env-entry/
    [env-entry-name="webVar1"]/
    env-entry-value</xpath>
    <operation>replace</operation>
   </variable-assignment>

   <variable-assignment>
    <name>WebEnv_Var2</name>
    <xpath>/web-app/env-entry/
    [env-entry-name="webVar2"]/
    env-entry-value</xpath>
    <operation>replace</operation>
   </variable-assignment>

  </module-descriptor>
 </module-override>
 <config-root></config-root>
</deployment-plan>

At the top we define the variables we want to use to override parameters:

<variable-definition>
 <variable>
  <name>WebEnv_Var1</name>
  <value>NEW environment variables from web.xml</value>
 </variable>
 <variable>
  <name>WebEnv_Var2</name>
  <value>800</value>
 </variable>
 <variable>
  <name>EjbEnv_Var1</name>
  <value>NEW environment variables from ejb-jar.xml</value>
 </variable>
 <variable>
  <name>EjbEnv_Var2</name>
  <value>900</value>
 </variable>
</variable-definition>

Then we use the <variable-assignment>-element to specify what we want to override with XPath. If you're not familiar with XPath, you should find a tutorial for explanation. Simply said, XPath makes it possible to "walk" to the element you want to override. The value string between the <xpath>-elements is actually one line. But for this blogpost, I need to split up the string, because otherwise it won't fit the blog.

<variable-assignment>
 <name>WebEnv_Var2</name>
 <xpath>/web-app/env-entry/
 [env-entry-name="webVar2"]/
 env-entry-value</xpath>
 <operation>replace</operation>
</variable-assignment>

This actually means: replace the content of the <env-entry-value>-element where the <env-entry-name> equals "WebVar2", with the value specified as "WebEnv_Var2" in the variable definitions.

If we deploy the same EAR-file, but this time with the deployment plan, the servlet will output:

webVar1: NEW environment variables from web.xml
webVar2: 800
ejbVar1: NEW environment variables from ejb-jar.xml
ejbVar2: 900

The environment parameters defined in the deployment plan successfully override the parameters defined in the deployment descriptors.

References:

• Understanding Oracle WebLogic deployment plans
  
• Deploying with a deployment plan