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

Mocking classes with JMock

Normally, you'll get the following exception when you try to mock a class with jMock:

java.lang.IllegalArgumentException:
  com.javaeenotes.YourClass is not an interface.

The solution is to use the ClassImposteriser when instantiating the Mockery class.

context = new Mockery() {
  {
    setImposteriser(ClassImposteriser.INSTANCE);
  }
};

Now you can mock any class, just as interfaces. The complete instructions can be found on this web page.

Introduction to Java Concurrency / Multithreading

I came across a nice complete article about Java Concurrency:

Introduction to Java Concurrency / Multithreading

Well written by Jakob Jenkov.

Short introduction to jMock

The jUnit framework is a great tool for testing your Java application. But writing test cases can be complex. Especially when the object under test is dependent on several other objects, which in turn depend on other objects. This means the whole dependency graph has to be created before the test can be executed. Building this graph can be complex, and error-prone.

Luckily for us, there exists a framework called jMock. jMock enables you to create mock objects that mimic behavior of dependent objects. We can configure the expected interaction and behavior of these objects.

Let's start with an example class we want to test:

package com.javaeenotes;

public class TestSubject {
    private DependentClassInterface depObject;

    public TestSubject(DependentClassInterface depObject) {
        this.depObject = depObject;
    }
    
    public String method() {
        return depObject.method();
    }
}

The class is dependent on a class with the following interface:

package com.javaeenotes;

public interface DependentClassInterface {
    public String method();
}

The interface specifies a method that returns a String. The actual implementation of this interface is not required for jMock. jMock uses the interface to create an object with the same interface you can use in your test cases.

An example test case:

package com.javaeenotes;

import static org.junit.Assert.assertTrue;

import org.jmock.Expectations;
import org.jmock.Mockery;
import org.junit.Test;

public class TestSubjectTest {
    @Test
    public void testMethod() {
        Mockery context = new Mockery();
        // Create mock object.
        final DependentClassInterface depObject = context
                .mock(DependentClassInterface.class);

        // Test object is instantiated with mock object.
        TestSubject testSubject = new TestSubject(depObject);

        // Configure expectation and behavior.
        context.checking(new Expectations() {
            {
                oneOf(depObject).method();
                will(returnValue("hello"));
            }
        });

        // Test outcome.
        assertTrue(testSubject.method().equals("hello"));

        // Check if expectations are satisfied.
        context.assertIsSatisfied();

  }
}

In this test case, we create the object under test with a mock object. The expected interaction and behavior is then configured. First, the method() method is called, which then returns a string value "hello". Other interactions, like calling the same method twice, will result in an error.

As you can see, jMock is a very valuable extension to the jUnit framework, which makes writing test cases much easier.

Links:

• http://www.jmock.org
  
• http://www.jmock.org/expectations.html
  

Note: when running jMock in Eclipse, the following error can occur when running test cases:

java.lang.SecurityException:
  class "org.hamcrest.TypeSafeMatcher"'s signer information
  does not match signer information of other classes in the
  same package

The solution is make sure the jMock libraries are included before the standard jUnit libraries in the build path.

Free resources associated with web clients

Imagine we have the following problem. Resources are kept open for web clients as long as the clients are using them. When they leave, the resources have to be closed.

Technically, we can say as long as the HttpSession is alive in the web container, the resources are kept open. When the HttpSession is invalidated, we need to call a method that frees the resources.

A solution is to use the HttpSessionBindingListener to solve this problem.

The idea is to create a class that implements this interface. The unbound method contains or refers to the clean-up code. Whenever resources are opened, an instance of this class is created and saved to the corresponding session. When the session invalidates, which can happen by timeout, the web container automatically calls the method of the object in order to free open resources.

The class:

package com.javaeenotes;

import javax.servlet.http.HttpSessionBindingEvent;
import javax.servlet.http.HttpSessionBindingListener;

public class Janitor implements HttpSessionBindingListener {

    public void valueBound(HttpSessionBindingEvent arg0) {
        ;
    }

    public void valueUnbound(HttpSessionBindingEvent arg0) {
        // Start some cleaning here.
    }
}

Use the HttpSession.setAttribute() method to save an instance of this class to the session.

Creating a Modal Window page with Apache Wicket

This post aims to clarify creating a modal window with Apache Wicket. Before continuing, minimum basic knowledge about Apache Wicket is required. A modal window is a child window on top of the main window. The modal window requires the user to interact with it, before the user can return to the main window.

The application we're developing consists of two pages:

• The main page (LaunchPage.java and LaunchPage.html)
  
• The modal window page (ModalContentPage.java and ModalWContentPage.html)
  

The main page defines and displays the content of a variable and it also has a link to open the modal window page.

The modal window page displays the content of the same variable. But when the modal window is closed, the variable is changed by the modal window page.

Let's start by creating the HTML-file of the main page.

<html>
<head>
<title>Launch Page</title>
</head>
<body>
<div wicket:id="modal"></div>
<span wicket:id="passValueLabel">Value of passValue variable.</span>
<a wicket:id="showModalLink">Open modal window.</a>
</body>
</html>

This page defines the modal page with id "modal". The next line is the location where the content of the variable "passValue" is displayed. Finally, a link is defined that opens the modal window.

Next, the corresponding Java class:

package com.javaeenotes;

import org.apache.wicket.Page;
import org.apache.wicket.ajax.AjaxRequestTarget;
import org.apache.wicket.ajax.markup.html.AjaxLink;
import org.apache.wicket.extensions.ajax.markup.html.modal.ModalWindow;
import org.apache.wicket.markup.html.WebPage;
import org.apache.wicket.markup.html.basic.Label;
import org.apache.wicket.model.PropertyModel;

public class LaunchPage extends WebPage {

    private String passValue;

    @SuppressWarnings("serial")
    public LaunchPage() {

        passValue = "This value is passed to the modal window.";

        // Display the current content of the passValue variable. The
        // PropertyModel must be used, as the value can be changed.
        final Label passValueLabel;
        add(passValueLabel = new Label("passValueLabel",
                new PropertyModel<String>(this, "passValue")));
        passValueLabel.setOutputMarkupId(true);

        // Create the modal window.
        final ModalWindow modal;
        add(modal = new ModalWindow("modal"));
        modal.setCookieName("modal-1");

        modal.setPageCreator(new ModalWindow.PageCreator() {
            public Page createPage() {
                // Use this constructor to pass a reference of this page.
                return new ModalContentPage(LaunchPage.this.getPageReference(),
                        modal);
            }
        });
        modal.setWindowClosedCallback(new ModalWindow.WindowClosedCallback() {
            public void onClose(AjaxRequestTarget target) {
                // The variable passValue might be changed by the modal window.
                // We need this to update the view of this page.
                target.add(passValueLabel);
            }
        });
        modal.setCloseButtonCallback(new ModalWindow.CloseButtonCallback() {
            public boolean onCloseButtonClicked(AjaxRequestTarget target) {
                // Change the passValue variable when modal window is closed.
                setPassValue("Modal window is closed by user.");
                return true;
            }
        });

        // Add the link that opens the modal window.
        add(new AjaxLink<Void>("showModalLink") {
            @Override
            public void onClick(AjaxRequestTarget target) {
                modal.show(target);
            }
        });
    }

    public String getPassValue() {
        return passValue;
    }

    public void setPassValue(String passValue) {
        this.passValue = passValue;
    }
}

The class file displays the content of "passValue" and creates the modal window class with its methods. Look carefully at the code and comments in the modal window methods. We can see that the passValueLabel is expected to change in the window close callback method. We can also see that the variable is actually changed using a setter in the close button callback method. This happens when the user clicks on the close button of the modal window. Finally, an AJAX link is defined and added to the page.

The second part is the modal window page:

<html>
<head>
<title>Modal Content Page</title>
</head>
<body>
<span wicket:id="passValueLabel">Current content of passValue variable.</span>
</body>
</html>

The modal page only displays the content of the "passValue" variable. The variable is owned by the main page.

package com.javaeenotes;

import org.apache.wicket.PageReference;
import org.apache.wicket.extensions.ajax.markup.html.modal.ModalWindow;
import org.apache.wicket.markup.html.WebPage;
import org.apache.wicket.markup.html.basic.Label;

public class ModalContentPage extends WebPage {

    public ModalContentPage(final PageReference modalWindowPage,
            final ModalWindow window) {

        // Retrieve the passValue content for display.
        String passValue = ((LaunchPage) modalWindowPage.getPage())
                .getPassValue();
        add(new Label("passValueLabel", passValue));

        // You can use the
        // ((LaunchPage)modalWindowPage.getPage()).setPassValue() method to
        // change the passValue variable of the launch/caller page.
    }
}

This class is pretty simple. The first parameter refers to the main page that created the modal window page. Go back, and look how the modal window page is constructed in the main page. The main page is casted and the variable is retrieved using the getter-method. The content is then displayed in the modal window page.

Now run the code and the main page will look like this:



After clicking the link, the modal window page is opened:



We can see the same variable is displayed in the modal window page. Now, we close the modal window page. Because of this event, the variable is changed as instructed in the callback code:



As expected, the variable is changed in the main window.