/usr/share/doc/liblogback-java/manual/loggingSeparation.html

<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.0 Transitional//EN" 
  "http://www.w3.org/TR/xhtml1/DTD/xhtml1-transitional.dtd">

<html xmlns="http://www.w3.org/1999/xhtml">
  <head>
    <meta http-equiv="content-type" content="text/html; charset=iso-8859-1" />
    <title>Chapter 9: Logging separation</title>
    <link rel="stylesheet" type="text/css" href="../css/common.css" />
    <link rel="stylesheet" type="text/css" href="../css/screen.css" media="screen" />
    <link rel="stylesheet" type="text/css" href="../css/_print.css" media="print" />
    <link rel="stylesheet" type="text/css" href="../css/prettify.css" media="screen" />
  </head>
  <body onload="prettyPrint()">
    <script type="text/javascript">prefix='../';</script>
    <script type="text/javascript" src="../js/prettify.js"></script>
    <script src="../templates/header.js" type="text/javascript"></script>
    <div id="left">
      <noscript>Please turn on Javascript to view this menu</noscript>
      <script src="../templates/left.js" type="text/javascript"></script>
    </div>
    <div id="right">
      <script src="menu.js" type="text/javascript"></script>
    </div>
    <div id="content">	
	
    <h1>Chapter 9: Logging separation</h1>
      
    <div class="quote">
      <p><em>It is not knowledge, but the act of learning, not
      possession but the act of getting there, which grants the greatest
      enjoyment. When I have clarified and exhausted a subject, then I
      turn away from it, in order to go into darkness again; the
      never-satisfied man is so strange if he has completed a structure,
      then it is not in order to dwell in it peacefully, but in order to
      begin another. I imagine the world conqueror must feel thus, who,
      after one kingdom is scarcely conquered, stretches out his arms
      for others.</em></p>

      <p>&mdash;KARL FRIEDRICH GAUSS, Letter to Bolyai, 1808.</p>

      <p><em>Style, like sheer silk, too often hides eczema.</em></p>
      
      <p>&mdash;ALBERT CAMUS, <em>The Fall</em></p>

    </div>

    <script src="../templates/creative.js" type="text/javascript"></script>		
    <script src="../templates/setup.js" type="text/javascript"></script>

    <h2>The problem: Logging Separation</h2>

    <p>The chapter deals with a relatively difficult problem of
    providing a separate logging environment for multiple applications
    running on the same web or EJB container. In the remainder of this
    chapter the term "application" will be used to refer to either a
    web-application or a J2EE application interchangeably.  In a
    separated logging environment, each application sees a distinct
    logback environment, so that the logback configuration of one
    application does not interfere with the settings of another. In
    more technical terms, each web-application has a distinct copy of
    <code>LoggerContext</code> reserved for its own use. Recall that
    in logback, each logger object is manufactured by a
    <code>LoggerContext</code> to which it remains attached for as
    long as the logger object lives in memory. A variant of this
    problem is the separation of application logging and the logging
    of the container itself.
    </p>

    <h2><a name="easy" href="#easy">The simplest and easiest
    approach</a></h2>

    <p>Assuming your container supports child-first class loading,
    separation of logging can be accomplished by embedding a copy of
    slf4j and logback jar files in each of your applications. For
    web-applications, placing slf4j and logback jar files under the
    <em>WEB-INF/lib</em> directory of the web-application is
    sufficient to endow each web-application with a separate logging
    environment. A copy of the <em>logback.xml</em> configuration file
    placed under <em>WEB-INF/classes</em> will be picked up when
    logback is loaded into memory. 
    </p>

    <p>By virtue of class loader separation provided by the container,
    each web-application will load its own copy of
    <code>LoggerContext</code> which will pickup its own copy of
    <em>logback.xml</em>.</p>
    
    <p>Easy as pie.</p>

    <p>Well, not exactly. Sometimes you will be forced to place SLF4J
    and logback artifacts in a place accessible from all applications,
    typically because a shared library uses SLF4J. In that case, all
    applications will share the same logging environment. There are
    various other scenarios where a copy of SLF4J and logback
    artifacts is necessarily placed at a spot where it can be seen by
    all applications making logging separation by class loader
    separation impossible. All hope is not lost. Please read on.
    </p>

    <h2><a name="contextSelectors" href="#contextSelectors">Context
    Selectors</a></h2>

    <p>Logback provides a mechanism for a single instance of SLF4J and
    logback classes loaded into memory to provide multiple logger
    contexts. When you write:
    </p>

    <pre class="prettyprint source">Logger logger = LoggerFactory.getLogger("foo");</pre>

    <p>the <code>getLogger</code>() method in
    <code>LoggerFactory</code> class will ask the SLF4J binding for a
    <code>ILoggerFactory</code>. When SLF4J is bound to logback, the
    task of returning an <code>ILoggerFactory</code> is delegated to
    an instance of <a
    href="../apidocs/ch/qos/logback/classic/selector/ContextSelector.html">ContextSelector</a>. Note
    that <code>ContextSelector</code> implementations always return
    instances <code>LoggerContext</code>. This class implements the
    <code>ILoggerFactory</code> interface.  In other words, a context
    selector has the option to returning any
    <code>LoggerContext</code> instance it sees fit according to its
    own criteria. Hence the name context <em>selector</em>.
    </p>

    <p>By default, the logback binding uses <a
    href="../xref/ch/qos/logback/classic/selector/DefaultContextSelector.html">DefaultContextSelector</a>
    which always returns the same <code>LoggerContext</code>, called
    the default logger context.</p>

    <p>You can specify a different context selector by setting the
    <em>logback.ContextSelector</em> system property. Suppose you
    would like to specify that context selector to an instance of the
    <code>myPackage.myContextSelector</code> class, you would add the
    following system property: </p>

    <p class="source">-Dlogback.ContextSelector=myPackage.myContextSelector</p>

    <p>The context selector needs to implement the
    <code>ContextSelector</code> interface and have a constructor
    method admitting a <code>LoggerContext</code> instance as its only
    parameter.
    </p>


    <h3><a name="ContextJNDISelector"
    href="#ContextJNDISelector">ContextJNDISelector</a></h3>

    <p>Logback-classic ships with a selector called
    <code>ContextJNDISelector</code> which selects the logger context
    based on data available via JNDI lookup. This approach leverages
    JNDI data separation mandated by the J2EE specification. Thus, the
    same environment variable can be set to carry a different value in
    different applications. In other words, calling
    <code>LoggerFactory.getLogger()</code> from different applications
    will return a logger attached to a different logger context, even
    if there is a single LoggerFactory class loaded into memory shared
    by all applications. That's logging separation for you.
    </p>

    <p>To enable <code>ContextJNDISelector</code>, the
    <em>logback.ContextSelector</em> system property needs to be set
    to "JNDI", as follows:</p>

    <p class="source">-Dlogback.ContextSelector=JNDI</p>

    <p>Note that the value <code>JNDI</code> is a convenient shorthand
    for
    <code>ch.qos.logback.classic.selector.ContextJNDISelector</code>.</p>

    <h3><a name="settingJNDIVariables"
    href="#settingJNDIVariables">Setting JNDI variables in
    applications</a></h3>
    
    <p>In each of your applications, you need to name the logging
    context for the application. For a web-application, JNDI
    environment entries are specified within the <em>web.xml</em>
    file. If "kenobi" was the name of your application, you would add
    the following XML element to kenobi's web.xml file:</p>

    <pre class="prettyprint source">&lt;env-entry>
  &lt;env-entry-name>logback/context-name&lt;/env-entry-name>
  &lt;env-entry-type>java.lang.String&lt;/env-entry-type>
  &lt;env-entry-value>kenobi&lt;/env-entry-value>
&lt;/env-entry></pre>

    <p>Assuming you have enabled <code>ContextJNDISelector</code>,
    logging for Kenobi will be done using a logger context named
    "kenobi". Moreover, the "kenobi" logger context will be
    initialized by <em>convention</em> by looking up the configuration
    file called <em>logback-kenobi.xml</em> as a <em>resource</em>
    using the thread context class loader. Thus, for example for the
    kenobi web-application, <em>logback-kenobi.xml</em> should be
    placed under the <em>WEB-INF/classes</em> folder.
    </p>

    <p>If you wish to, you may specify a different configuration file
    other than the convention, by setting the
    "logback/configuration-resource" JNDI variable. For example, for
    the kenobi web-application, if you wish to specify
    <em>aFolder/my_config.xml</em> instead of the conventional
    <em>logback-kenobi.xml</em>, you would add the following XML
    element to web.xml
    </p>


   <pre class="prettyprint source">&lt;env-entry>
  &lt;env-entry-name>logback/configuration-resource&lt;/env-entry-name>
  &lt;env-entry-type>java.lang.String&lt;/env-entry-type>
  &lt;env-entry-value>aFolder/my_config.xml&lt;/env-entry-value>
&lt;/env-entry></pre> 

    <p>The file <em>my_config.xml</em> should be placed under
    <em>WEB-INF/classes/aFolder/</em>. The important point to remember
    is that the configuration is looked up as a Java resource using
    the current thread's context class loader.
    </p>
    

    <h3><a name="jndiTomcat" href="#jndiTomcat">Configuring Tomcat for
    ContextJNDISelector</a></h3>

    <p>First, place the logback jars (that is
    logback-classic-1.0.0.jar,
    logback-core-1.0.0.jar and
    slf4j-api-1.6.4.jar) in Tomcat's global (shared) class
    folder. In Tomcat 6.x, this directory is
    <em>$TOMCAT_HOME/lib/</em>.
    </p>

    <p>The <em>logback.ContextSelector</em> system property can be set
    by adding the following line to the <em>catalina.sh</em> script,
    catalina.bat in Windows, found under <em>$TOMCAT_HOME/bin</em>
    folder.</p>

    <p class="source">JAVA_OPTS="$JAVA_OPTS -Dlogback.ContextSelector=JNDI"</p>


    <h3><a name="hotDeploy" href="#hotDeploy">Hot deploying
    applications</a></h3>

    <p>When the web-application is recycled or shutdown, we strongly
    recommend that the incumbent <code>LoggerContext</code> be closed
    so that it can be properly garbage collected. Logback ships with a
    <code>ServletContextListener</code> called <a
    href="../xref/ch/qos/logback/classic/selector/servlet/ContextDetachingSCL.html"><code>ContextDetachingSCL</code></a>,
    designed specifically for detaching the
    <code>ContextSelector</code> instance associated with the older
    web-application instance. It can be installed by adding the
    following lines into your web-applications <em>web.xml</em>
    file.</p>

    <pre class="prettyprint source">&lt;listener>
  &lt;listener-class>ch.qos.logback.classic.selector.servlet.ContextDetachingSCL&lt;/listener-class>
&lt;/listener></pre>

    <h3><a name="betterPerf" href="betterPerf">Better
    performance</a></h3>

    <p>When <code>ContextJNDISelector</code> is active, each time a
    logger is retrieved, a JNDI lookup must be performed. This can
    negatively impact performance, especially if you are using
    non-static (a.k.a. instance) logger references. Logback ships with a
    servlet filter named <a
    href="../xref/ch/qos/logback/classic/selector/servlet/LoggerContextFilter.html">LoggerContextFilter</a>,
    specifically designed to avoid the JNDI lookup cost. It can
    be installed by adding the following lines to your application's
    web.xml file.</p>

 <pre class="prettyprint source">&lt;filter>
  &lt;filter-name>LoggerContextFilter&lt;/filter-name>
  &lt;filter-class>ch.qos.logback.classic.selector.servlet.LoggerContextFilter&lt;/filter-class>
&lt;/filter>
&lt;filter-mapping>
  &lt;filter-name>LoggerContextFilter&lt;/filter-name>
  &lt;url-pattern>/*&lt;/url-pattern>
&lt;/filter-mapping></pre>

   <p>At the beginning of each http-request,
   <code>LoggerContextFilter</code> will obtain the logger context
   associated with the application and then place it in a
   <code>ThreadLocal</code> variable. <code>ContextJNDISelector</code>
   will first check if the <code>ThreadLocal</code> variable is
   set. If it is set, then JNDI lookup will skipped. Note that at the
   end of the http request, the <code>ThreadLocal</code> variable will
   be nulled.  Installing <code>LoggerContextFilter</code> improves
   logger retrieval performance by a wide margin.
   </p>

   <p>Nulling the <code>ThreadLocal</code> variable allows garbage
   collection of the web-application when it is stopped or
   recycled.</p>


   <h2><a name="tamingStaticRefs" href="#tamingStaticRefs">Taming
   static references in shared libraries</a></h2>

   <p><code>ContextJNDISelector</code> works nicely to create logging
   separation when SLF4J and logback artifacts are shared by all
   applications. When <code>ContextJNDISelector</code> is active, each
   call to <code>LoggerFactory.getLogger()</code> will return a logger
   belonging to a logger context associated with the calling/current
   application.</p>

   <p>The common idiom for referencing a logger is via a static
   reference. For example,
   </p>

   <pre class="prettyprint source">public class Foo {
  <b>static</b> Logger logger = LoggerFactory.getLogger(Foo.class);
  ...
}</pre>

    <p>Static logger references are both memory and CPU
    efficient. Only one logger reference is used for all instances of
    the class. Moreover, the logger instance is retrieved only once,
    when the class is loaded into memory. If the host class belongs to
    some application, say kenobi, then the static logger will be
    attached to kenobi's logger context by virtue of
    <code>ContextJNDISelector</code>. Similarly, if the host class
    belongs to some other application, say yoda, then its static
    logger reference will be attached to yoda's logger context, again
    by virtue of <code>ContextJNDISelector</code>.
    </p>
    
    <p>If a class, say <code>Mustafar</code>, belongs to a library
    shared by both <em>kenobi</em> and <em>yoda</em>, as long as
    <code>Mustafar</code> has non static loggers, each invocation of
    <code>LoggerFactory.getLogger()</code> will return a logger
    belonging to a logger context associated with the calling/current
    application. But if <code>Mustafar</code> has a static logger
    reference, then its logger will be attached to the logger context of the
    application that calls it first. Thus,
    <code>ContextJNDISelector</code> does not provide logging
    separation in case of shared classes using static logger
    references. This corner case has eluded a solution for eons.</p>


    <p>The only way to solve this issue transparently and perfectly
    would be to introduce another level of indirection inside loggers
    so that each logger-shell somehow delegated work to an inner
    logger attached to the appropriate context. This approach would be
    quite difficult to implement and would incur a significant
    computational overhead. It is not an approach we plan to pursue.
    </p>

    <p>It goes without saying that one could trivially solve the
    "shared class static logger" problem by moving the shared classes
    inside the web-apps (unshare them). If unsharing is not possible,
    then we can solicit the magical powers of <a
    href="appenders.html#SiftingAppender"><code>SiftingAppender</code></a>
    in order to separate logging using JNDI data as separation
    criteria.
    </p>

    <p>Logback ships with a discriminator called <a
    href="../xref/ch/qos/logback/classic/sift/JNDIBasedContextDiscriminator.html">JNDIBasedContextDiscriminator</a>
    which returns the name of the current logger context as computed
    by <code>ContextJNDISelector</code>. The
    <code>SiftingAppender</code> and
    <code>JNDIBasedContextDiscriminator</code> combination will create
    separate appenders for each web-application.
    </p>

    <pre class="prettyprint source">&lt;configuration>

  &lt;statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />  

  &lt;appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
    &lt;discriminator class="ch.qos.logback.classic.sift.JNDIBasedContextDiscriminator">
      &lt;defaultValue>unknown&lt;/defaultValue>
    &lt;/discriminator>
    &lt;sift>
      &lt;appender name="FILE-${contextName}" class="ch.qos.logback.core.FileAppender">
        &lt;file><b>${contextName}.log</b>&lt;/file>
        &lt;encoder>
          &lt;pattern>%-50(%level %logger{35}) cn=%contextName - %msg%n&lt;/pattern>
         &lt;/encoder>
      &lt;/appender>
     &lt;/sift>
    &lt;/appender>

  &lt;root level="DEBUG">
    &lt;appender-ref ref="SIFT" />
  &lt;/root>
&lt;/configuration></pre>


   <p>If kenobi and yoda are web-applications, then the above
   configuration will output yoda's log output to <em>yoda.log</em>
   and kenobi's logs to <em>kenobi.log</em>; this even works for logs generated
   by static logger references located in shared classes.</p>
 
   <p>You can try out the technique just described with the help of the
   <a
   href="http://github.com/ceki/logback-starwars">logback-starwars</a>
   project.
   </p>
 
 
   <p>The above approach solves the logging separation problem but is
   rather complex. It requires the proper installation of
   <code>ContextJNDISelector</code> and mandates that appenders be
   wrapped by <code>SiftingAppender</code> which is a non-trivial beast
   in itself.
   </p>
 
   <p>Note that each logging context can be configured using the same
   file or alternatively different files. The choice is up to
   you. Instructing all contexts to use the same configuration file
   is simpler as only one file has to be maintained.  Maintaining a
   distinct configuration file for each application is harder to
   maintain but allows for more flexibility.</p>
 
   <p>So are we done yet? Can we declare victory and go home? Well, not
   quite.</p>
 
   <p>Let's assume the web-application <code>yoda</code> is initialized
   before <code>kenobi</code>. To initialize <code>yoda</code>, visit
   <code>http://localhost:port/yoda/servlet</code> which will invoke
   the <code>YodaServlet</code>. This servlet just says hello and logs
   message before calling the <code>foo</code> method in
   <code>Mustafar</code> which not-surprisingly logs a simple message
   and returns.
   </p>
 
   <p>After <code>YodaServlet</code> is called, the contents of
   <em>yoda.log</em> file should contain</p>
 
   <pre class="source">DEBUG ch.qos.starwars.yoda.YodaServlet             cn=yoda - in doGet()
DEBUG ch.qos.starwars.shared.Mustafar              cn=yoda - in foo()</pre>
 
   <p>Note how both log entries are associated with the "yoda" context
   name. At this stage and until the server stops, the
   <code>ch.qos.starwars.shared.Mustafar</code> logger is attached to
   the 'yoda' context and will remain so until the server is stopped.
   </p>

   <p>Visiting <code>http://localhost:port/kenobi/servlet</code> will
   output the following in <em>kenobi.log</em>.</p>

   <pre class="source">DEBUG ch.qos.starwars.kenobi.KenobiServlet          <b>cn=kenobi</b> - in doGet()
DEBUG ch.qos.starwars.shared.Mustafar               <b>cn=yoda</b> - in foo()</pre>

   <p>Note that even if the
   <code>ch.qos.starwars.shared.Mustafar</code> logger outputs to
   <em>kenobi.log</em> it is still attached to 'yoda'. Thus, we have
   two distinct logging contexts logging to the same file, in this
   case <em>kenobi.log</em>. Each of these contexts reference
   <code>FileAppender</code> instances, nested within distinct
   <code>SiftingAppender</code> instances, that are logging to the same
   file. Although logging separation seems to function according to
   our wishes, FileAppender instances cannot safely write to the same
   file unless they enable <span class="option">prudent</span>
   mode. Otherwise, the target file will be corrupted.</p>
   
   <p>Here is the configuration file enabling prudent mode:</p>

    <pre class="prettyprint source">&lt;configuration>

  &lt;statusListener class="ch.qos.logback.core.status.OnConsoleStatusListener" />  

  &lt;appender name="SIFT" class="ch.qos.logback.classic.sift.SiftingAppender">
    &lt;discriminator class="ch.qos.logback.classic.sift.JNDIBasedContextDiscriminator">
      &lt;defaultValue>unknown&lt;/defaultValue>
    &lt;/discriminator>
    &lt;sift>
      &lt;appender name="FILE-${contextName}" class="ch.qos.logback.core.FileAppender">
        &lt;file>${contextName}.log&lt;/file>
        <b>&lt;prudent>true&lt;/prudent></b>
        &lt;encoder>
          &lt;pattern>%-50(%level %logger{35}) cn=%contextName - %msg%n&lt;/pattern>
         &lt;/encoder>
      &lt;/appender>
     &lt;/sift>
    &lt;/appender>

  &lt;root level="DEBUG">
    &lt;appender-ref ref="SIFT" />
  &lt;/root>
&lt;/configuration></pre>


   <p>If you were able to keep up with the discussion thus far and
   have actually tried the logback-starwars examples, then you must be
   truly obsessed with logging. You should consider seeking <a
   href="http://www.qos.ch/shop/products/professionalSupport">professional
   help</a>.</p>



   <script src="../templates/footer.js"
   type="text/javascript"></script> </div>
   
   </body> 
</html>
liblogback-java-doc 1:1.0.0-1 / usr / share / doc / liblogback-java / manual / loggingSeparation.html
