Logback Demo

Welcome to the logback demo! This document will take you through tour that will show you some of the major features of logback.

Installation

First, please download the logback demo. You will need to install a Subversion client and issue the following command on a console:

svn co http://svn.qos.ch/repos/logback-demo/trunk logback-demo

This will checkout a copy of the logback demonstration web-app to a directory called logback-demo. The logback demo can be packaged as a war file and deployed to an application server. We strongly recommend the use of Maven2 to do this task, since all it will take to compile, package and run a server with the demo is a single command.

Using Maven, let's package the files and run the demo for the first time. From the logback-demo directory, issue the following command:

mvn package jetty:run

Then, visit http://localhost:8080/logback-demo/ to view the main page of the logback demo.

Logback Classic

For now, logback uses two components: one ConsoleAppender and one RollingFileAppender. The RollingFileAppender sends logging events to a file called logFile.log and will rollover the active file every minute. The old file will be renamed and compressed to zip file. The ConsoleAppender will output the logging requests to the console, and shorten the logger names to gain some space in the console window, without making the names unreadable. For example, ch.qos.logback.demo.prime.NumberCruncherImpl will be displayed as c.q.l.d.prime.NumberCruncherImpl.

You can study the configuration file that is used by editing the file called logback.xml, located in the src/main/resources/ directory of the demo. You might want to keep this file in an editor window, since we will modify its content several times thoughout the demo.

Let's now visit the ViewStatii page, via the navigation menu on the left hand of the navigator window. This page contains the content of the Status objects that were created until now. Status objects are a part of logback's powerful internal reporting framework. They allow you to see what is going on in logback, and check that a configuration file has been parsed correctly, or that a rollover has occured as expected.

After you're back to the main window, visiting the View logs page does not impress much at the moment. Let us uncomment the two parts of the config file that are below the Cyclic buffer comment. A CyclicBuffer is a class that keeps track of logging events and holds these objects for immediate or differed display. The first element that you will need to uncomment is the appender element. This element describes and configures the CyclicBuffer. The second element, found at the end of the configuration file, is a appender-ref element. It is used to link the appender to a given logger. Now reload the web-app by exiting the previous command with CTRL-C and issuing it again: mvn package jetty:run.

Now, the View logs page looks prettier. By virtue of the CyclicBufferAppender, this page can fetch the last events and present them through a servlet. We see that each 3 seconds a line is added to the logs. The formatting of this page is made with a HTMLLayout. This component creates a nice and readable table containing the logging events, based on a pattern that describes the information one wants to see in the table.

Having the logs that we see on the web page cluttered with scheduled Howdydy-diddly-ho messages is not very comfortable. To get rid of these logs, now that we've verified that they work, we can add an EvaluatorFilter to the Appender. Uncomment the part named Cyclic buffer with Evaluator. You may then comment the first Basic Cyclic buffer appender element.

Let's take a look at the filter we've just added:

<filter class="ch.qos.logback.core.filter.EvaluatorFilter">
  <evaluator name="loggingTaskEval">
    <expression>
      logger.getName().contains("LoggingTask") &amp;&amp;
      message.contains("Howdydy-diddly-ho") &amp;&amp;
      (timeStamp - event.getStartTime()) >= 20000
    </expression>
  </evaluator>
  <OnMatch>DENY</OnMatch>
</filter>

The expression element contains a familiar java statement. This expression checks that the name of the logger contains the String LoggingTask, but also that the message accompagnying the log contains Howdydy-diddly-ho. Moreover, in order to be sure that the Howdydy-diddly-ho task actually works, we add to the expression a last statement that allows logs to be processed for the first 20 seconds after the application launch. The variables used in this statement (logger, message and event) are made available by logback before the filter evaluates the expression. The OnMatch element allows the user to choose the filter's behaviour once the expression was evaluated to true. A similar OnMismatch element exists.

After a restart, the Vew logs page shows the Howdydy-diddly-ho logs for the first 20 seconds only. Trying a prime calculations on the Prime number page will add several lines to the View logs page.

Turbo Filters

Logback ships with a special category of filters: TurboFilter objects are ultra-fast, context-wide filters. They reveals themselves very useful to test MDC values, for examples and to add context-wide conditions to allow or deny logging events. Let's uncomment the part named TurboFilter: MDC value in the logback.xml file.

This part adds a TurboFilter object to the context. It allows to have a typical output for every client that uses the demo application, but a different one for one given user. Here, the filter will accept all the requests that are associated with a MDC value of sebastien bound to the username key.

To view the consequences of such a TurboFilter, we are going to stop all logging activity, except for a specific user. To achieve that, the simplest way is to set the root logger's level to OFF. Modify the level element, nested inside the root element of logback.xml. Its value attribute should be OFF instead of DEBUG. Next, restart the server as we've done previously.

Once on the demo main webpage again, perform a few actions (i.e. calculate a few prime numbers) and watch the View logs page. The table should be empty.

Now log in the application using the username sebastien and perform a few prime calculations again. The View logs page now shows the logs that were generated by the calculation classes. Moreover, each log is associated with the name of the user who provoked the logging event. Please log off before continuing the demo, using the logout button on the left.

Parametrized logging

Parametrized logging is a feature that will be a great asset for any performance-critical system. Usually, a logging request is issued like this:

logger.debug("Hello, my name is" + username + ", I am " + age + " years old.");

By issuing this line, the cost of constructing the String cannot be saved when the log request is not processed. For example, using the debug() method when, as we've just done, the root level is any value higher that DEBUG will result in a loss of time because all calls to the debug() method will eventually be dropped.

Logback offers the following method:

logger.debug("Hello, my name is {}, I am {} years old", username, age);

As you can see, the variables are not inserted in the message yet. Both the message and the values will be saved and used later, if the logging event is processed.

Let us now run a test to see what kind of gain can we expect from this different message formatting approach. First, go to the Prime number page and run a few calculations. Check the time it takes to compute the results. To see a clearer difference between the two formatting methods, you might want to try the two big integers that are listed below the prime number textbox.

Now let us edit the NumberCruncherImpl class, to switch the log methods. You will find this class in the src/main/java/ch/qos/logback/demo/prime/ directory. On line 54 and 55, just uncomment the parametrized logging line and comment out the other line. Restart the server with mvn package jetty:run and re-run the calculations you tried beforehand.

The durations should be obviously different. Remember that we had turned off all logging in the previous step of this demo. With the initial formatting method, we were constructing the logging message ("Trying "+i+" as a factor.") a huge amount of times, actually each time a factor was tried for these big numbers. With the paramatrized logging, the construction of the message was postponed and, since logging was turned off, not processed. We see here that the cost of the non-logging was taken down to a very small figure, dividing the total cost of the calculation by a non-negligeable factor.

Markers

SLF4J allows the use of Marker objects. For example, one could use TRACE markers, to enrich some specific logging statements. In our demo applications, the Howdydy-diddly-ho logging statements are bound to a TRACE marker. On the other hand, one could want that such marked statements be dropped and not logged anywhere. TurboFilter objects can do that in an elegant and flexible way. Let us uncomment the TurboFilter: Marker value section in the logback.xml file as well as set the root logger's level back to DEBUG, and reload via the Reload configuration page.

The logging statements that contained the Howdydy-diddly-ho do not appear anymore because they were associated with a TRACE marker. You can check that by visiting the View Logs page and reloading it every three seconds for several times.

Logback Access

Access logging is another important feature offered by logback. Give a look at what appears on the console while browsing the logback-demo website. Each access is logged to the console, with some information about the event. The configuration file that we will edit in the next few steps is called logback-access.xml and is located in the src/etc/ directory. The necessary configuration is listed below:

<configuration>
 
  <appender name="STDOUT"
    class="ch.qos.logback.core.ConsoleAppender">
    <layout class="ch.qos.logback.access.PatternLayout">
      <Pattern>%h %l %u %t \"%r\" %s %b</Pattern>
    </layout>
  </appender>
  
  <appender-ref ref="STDOUT" />
  
</configuration>

To see more clearly the output produced by logback access, you might want set the root logger's level to OFF, in the first logback configuration file, called logback.xml and located in src/main/resources/. It will clear the console from the logs made by the demo application and only display those that are generated by logback access.

To see the logs produced by logback access, just visit a few pages and look at your console. The information contained in each line has been specified in the configuration file. The ConsoleAppender named STDOUT contains a PatternLayout component. This very component that one uses in logback classic to display either the message, logger name or level of the request is used in logback access to display the request method, requested page, status code and many others.

Here is a sample output of this appender.

127.0.0.1 - - 22/01/2007:14:35:40 +0100 GET /logback-demo/ViewStatii.do HTTP/1.1 200 3660
127.0.0.1 - - 22/01/2007:14:35:41 +0100 GET /logback-demo/index.jsp HTTP/1.1 200 2389
127.0.0.1 - - 22/01/2007:14:35:42 +0100 GET /logback-demo/lastLog/ HTTP/1.1 200 948
127.0.0.1 - - 22/01/2007:14:35:42 +0100 GET /logback-demo/index.jsp HTTP/1.1 200 2389
127.0.0.1 - - 22/01/2007:14:35:43 +0100 GET /logback-demo/prime.jsp HTTP/1.1 200 1296
127.0.0.1 - - 22/01/2007:14:35:44 +0100 GET /logback-demo/index.jsp HTTP/1.1 200 2389
127.0.0.1 - - 22/01/2007:14:35:45 +0100 GET /logback-demo/lottery.jsp HTTP/1.1 200 1209
127.0.0.1 - - 22/01/2007:14:35:46 +0100 GET /logback-demo/index.jsp HTTP/1.1 200 2389
127.0.0.1 - - 22/01/2007:14:35:48 +0100 GET /logback-demo/reload.jsp HTTP/1.1 200 1335
127.0.0.1 - - 22/01/2007:14:35:49 +0100 GET /logback-demo/index.jsp HTTP/1.1 200 2389
127.0.0.1 - - 22/01/2007:14:35:54 +0100 GET /logback-demo/login.jsp HTTP/1.1 200 1214
127.0.0.1 - - 22/01/2007:14:35:55 +0100 GET /logback-demo/Logout.do HTTP/1.1 200 1000

Filtering

In this next part, we are going to add some information to the console. Let us imagine that we want to log the numbers that are tried on the Lottery page. We will need a second ConsoleAppender that will only print a given information (e.g. the guessed number, along with some hints about the player). The appender will also have to print that information only when a certain page is accessed.

The configuration lines that are necessary are listed below.

<appender name="STDOUT_LOTTERY"
  class="ch.qos.logback.core.ConsoleAppender">
  <filter class="ch.qos.logback.core.filter.EvaluatorFilter">
    <evaluator name="lotto_eval">
      <Expression>
        url.matches(event.getRequestURL().toString())
      </Expression>
      <matcher name="url">
        <regex>Lottery.do</regex>
        <caseSensitive>false</caseSensitive>
      </matcher>
    </evaluator>
    <OnMatch>ACCEPT</OnMatch>
    <OnMismatch>DENY</OnMismatch>
  </filter>
  <layout class="ch.qos.logback.access.PatternLayout">
    <Pattern>
      LOTTERY: %A [%r] Guess=%reqParameter{guessed_number}
    </Pattern>
  </layout>
</appender>

This appender will use a PatternLayout to format its output. The %reqParameter conversion word is used to extract the guessed number from the request, and print it.

It also uses an EvaluatorFilter that will prevent the appender to display anything when the access' request url does not match the given expression. You can see that it is easy to specify a RegExp, name it and use it in the expression that will be evaluated. In that case, we only entered the name of the lottery.do action.

Let us uncomment the two elements with the Lottery to Console comments and restart the server. Now, try to play the lottery. You will see more lines in the Console that you've seen until now. At every try, logback will produce a log as shown below:

LOTTERY: 192.168.1.6 [POST /logback-demo/Lottery.do HTTP/1.1] Guess=321

Sending emails

Logback access provides several components that are usually used by the classic module. For example, a SMTPAppender can be used to send an email when a specific event occurs. Here, we will contact the lottery administrator each time a winner is detected. To achieve this, we will add a SMTPAppender to the existing configuration. Please uncomment the part of logback-access.xml named Lottery to Email. Do not forget to uncomment the appender-ref element, at the end of the configuration file, referencing the appender called SMTP. In the appender element, notice the use of a URLEvaluator. This evaluator allows us to only specify one or more URLs that have to be watched. When one of them are accessed, an email is sent.

A reload of the configuration has to be done before we can test this new component. Once done, try to play the lottery with the number 99. You should see a congratulation message but, most importantly, the specified recipients should have a new mail in their mailbox. The content of the email is a nicely formatted HTML table with informations about the access that have occured before the triggering event.

JMX

Logback publishes several components via JMX. This allows you to see the status of certain objects, and change several configuration parameters. Publishing logback's components via JMX is possible with Jetty and Tomcat.

To see logback access' components, visit the following page:

http://localhost:8082/

The domain ch.qos.logback.access.jetty contains an entry that allows you to see the RequestLogImpl component. This component is used to plug logback in Jetty's internal achitecture. Clicking on it reveals the status of several parameters, such as the started status, and two methods are available to start and stop the RequestLogImpl.

To see the influence of the available operations, place the terminal window and your web browser such that you can see them both. Stop the RequestLogImlp and reload a few times the main page of the demo. Nothing should be displayed. If you start the RequestLogImpl again, the requests will be shown in the terminal window.

In the logback-access.xml configuration file, uncomment the JMX part and restart the server. A CountingFilter will now be available in the ch.qos.logback.access domain. Clicking on it will display several statistical figures corresponding to server accesses. Loading some application pages will make these figures grow and show a time-sensitive picture of the server activity.

These is more to discover with logback and JMX. In the logback.xml file, placed in the src/main/resources directory, uncomment the JMXConfigurator element. Once done, restart the server.

By refreshing the previously loaded JMX page, you should see a new component, under the domain ch.qos.logback.classic. It is the JMXConfigurator. Clicking on it reveals its content. Its possibilities are listed below:

Reload the configuration using the same file that was previously used.

Reload the configuration using a file whose path is passed as a parameter.

Reload the configuration using a file whose URL is passed as a parameter.

Get the level of a logger

Change the level setting of a specified logger.

Change a list of all declared loggers.

Change the level setting of a specified logger.

In the last case, you must specify the name of the logger you wish to alter, and its new level.

Checking the level of a logger is an easy task. Enter the name of the logger in the appropriate field and click the Invoke button. You should be able to verify that the logger named root has its level set to OFF.

Let us test the level setting possibility of the configurator. The Prime Number page requests two types of logs. When the calculation checks if a number is a factor, a DEBUG log is displayed. When the calculation has found a factor, a INFO log is displayed.

Let us first set the level of the logger named ch.qos.logback.demo.prime to DEBUG. Run a prime calculation directly, without restarting the server. The View logs page should show the DEBUG and INFO logs.

Now, if you set the level of the ch.qos.logback.demo.prime logger to INFO, and run a prime calculation again, you should not see the DEBUG level logs anymore.

This demo of logback is now over. Do not hesitate to play around with the configuration files. You might want to check the logback documentation page for more information about any component you'd like to test.