log4j Notes

Table of Contents

Using log4j
External modification of log4j behavior (properties)
A more basic variation
Other behavior variations
Properties: logging level
More on properties: set logging level
Performance
Web applications
log4j from Eclipse
Where to put log4j.properties?
Where to put log4j.properties (or log4j.xml): round 2
log4j.properties with support for JSF and Spring
Java service wrapper
Changing level at runtime
Some links...
A great example of a production properties file
Errors encountered and solved
Locking when logging—performance considerations
Configuring log4j starting in v2
Log4j2
Logging sins
Outputting package paths in log
%-5level
Pattern layout in log4j.xml
tilde (~) and brackets

Using log4j

log4j logging is pretty easy. Here's a good tutorial: http://www.developer.com/open/article.php/10930_3097221_1, but you'll find better illustration on this page once you've spent the time on the concepts there. The bonafide Apache tutorial (log4j is an Apache thing) is at: http://logging.apache.org/log4j/1.2/manual.html and it's a good resource once you've read the first one and mine here unless you prefer more formal language.

Source code sample

Here is the sample code for the output we'll be studying. What's in italics and bold will vary for our examples.

package com.etretatlogiciels.samples.log4j;

import org.apache.log4j.Logger;

public class Log4J
{
  private static Logger   logger = Logger.getLogger( Log4J.class.getName() );
  private SimpleLayout    myLayout;
  private Appender        myAppender;

  public Log4J()
  {
    logger.setLevel( Level.INFO );
    myLayout   = new SimpleLayout();
    myAppender = new ConsoleAppender( myLayout );
    logger.addAppender( myAppender );
  }

  public static void do_something( int a, float b )
  {
    double   X = b - a - 3.1415;

    logger.info ( "Parameters passed to method do_something are: " + a + ", " + b );
    logger.debug( "Operation performed successfully" );
    logger.error( "Value of X is " + X );
  }

  public static void main( String[] args )
  {
    PropertyConfigurator.configure( "src/resources/log4j.properties" );
    do_something( 99, 542 );
  }
}

External modification of log4j behaviors (properties)

Given the above code, here is an option properties file that can tailor, without need to rebuild the code, the behavior of the logging. In particular, note SimpleLayout below. Despite coding to use SimpleLayout above, we can vary the behavior widely as shown here.

log4j.properties

Note the call to PropertyConfigurator.configure() in main() above; the properties file is placed on the path <project-name>/src/resources/log4j.properties. Its text consists of:

log4j.rootLogger=debug, myAppender
log4j.appender.myAppender=org.apache.log4j.ConsoleAppender
log4j.appender.myAppender.layout=org.apache.log4j.SimpleLayout

Note: the placement of the properties file and the argument passed to the PropertyConfigurator.configure() method is annoyingly difficult when using Eclipse. Please see a better working example below.

myAppender in this properties file is, of course, the very variable in the code. It must be identical. Some examples of console output while varying SimpleLayout in the properties file are:

SimpleLayout

Yeah, this is a sort of default. Here's what comes out in the Eclipse Console tab when you run the code:

INFO - Parameters passed to method do_something are: 99, 542.0
DEBUG - Operation performed successfully
ERROR - Value of X is 439.8585

PatternLayout

With this scheme, you lose the labels for whatever reason there is behind that.

Parameters passed to method do_something are: 99, 542.0
Operation performed successfully
Value of X is 439.8585

HTMLLayout

This gives you HTML output that can be nicely browsed:

Log session start time Tue Oct 14 16:27:31 MDT 2008

Time Thread Level Category Message
0 main INFO com.etretatlogiciels.samples.logging.Log4J Parameters passed to method do_something are: 99, 542.0
2 main DEBUG com.etretatlogiciels.samples.logging.Log4J Operation performed successfully
2 main ERROR com.etretatlogiciels.samples.logging.Log4J Value of X is 439.8585

DateLayout

Deprecated? I don't know why this isn't working in my set up, except that I looked at the class documentation and much of it was deprecated. I'll be figuring this out because most logging is done using a timestamp for obvious reasons.

java.lang.ClassNotFoundException:org.apache.log4j.DateLayout

XMLLayout

Didn't work. The doc doesn't say it's deprecated (unlike DateLayout) and it's also not full, legal XML, but only XML that you can tuck inside the surrounding tag of a full, legal file.

java.lang.ClassNotFoundException:org.apache.log4j.XMLLayout

A more basic variation

A more basic behavior can be had by simplifying the code above. You don't need a log4j.properties file.

package com.etretatlogiciels.samples.log4j;

import org.apache.log4j.Logger;
import org.apache.log4j.BasicConfigurator;

public class Log4J
{
  private static Logger   logger = Logger.getLogger( Log4J.class.getName() );
  private SimpleLayout    myLayout;
  private Appender        myAppender;

  public Log4J()
  {
    logger.setLevel( Level.INFO );
    myLayout   = new SimpleLayout();
    myAppender = new ConsoleAppender( myLayout );
    logger.addAppender( myAppender );
  }

  public static void do_something( int a, float b )
  {
    double   X = b - a - 3.1415;

    logger.info ( "Parameters passed to method do_something are: " + a + ", " + b );
    logger.debug( "Operation performed successfully" );
    logger.error( "Value of X is " + X );
  }

  public static void main( String[] args )
  {
    BasicConfigurator.configure();
    do_something( 99, 542 );
  }
}

Other behavior variations

If you change the properties file above to use info in place of debug:

log4j.rootLogger=info, appender
log4j.appender.appender=org.apache.log4j.ConsoleAppender
log4j.appender.appender.layout=org.apache.log4j.DateLayout

...you get (in simple-layout mode):

INFO - Parameters passed to method do_something are: 99, 542.0
ERROR - Value of X is 439.8585

...and you're now missing the DEBUG log line because DEBUG is left off and ERROR is higher in value. (The appender puts out the level set to, plus all higher-valued levels). The levels in ascending order are:

  1. DEBUG
  2. INFO
  3. WARN
  4. ERROR
  5. FATAL

To console, to file, to ?

We don't vary ConsoleAppender to FileAppender, JDBCAppender, SocketAppender, etc. in this sample because we want the output to go othe console for our demonstration. However, these are possibilities. What additional information must be supplied we don't yet know.


Logging level

To change the "global" (whole application) logging level (from INFO to DEBUG, etc.), edit log4j.properties:

log4j.rootLogger=DEBUG, ...

It's important to understand levels and their effect on what's to be logged. If the event level is greater or equal to the logger's level, then that even is printed out (wherever and however its appender is supposed to put it out). Crudely put, if the even level is set to TRACE, then everything gets printed. Here's a table:

FATAL ERROR WARN INFO DEBUG TRACE ALL
OFF
FATAL x
ERROR x x
WARN x x x
INFO x x x x
DEBUG x x x x x
TRACE x x x x x x
ALL x x x x x x x

For example, if the event level is set to INFO, whose cell colors in the table above are highlighted green, the following logging statements would reach the log file:

...but, not DEBUG or TRACE.

In logback.xml or whatever configuration file you're using, INFO is set thus:

<logger name="com.etretatlogiciels" level="INFO" additivity="false">
  <appender-ref ref="CONSOLE"/>
</logger>

More on properties: set logging level

The properties file (or the .xml variant) can be used to set the logging level for classes individually.

log4j.logger.com.acme=DEBUG
log4j.logger.org.springframework=DEBUG
log4j.logger.javax.faces=TRACE
log4j.logger.org.apache.myfaces=TRACE
log4j.logger.com.sun.faces=INFO

Performance

There are performance issues with log4j. If it's configured not to log, then it adds only the overhead of a function call and an integer compare. However, if the parameters to logger are complex conversions, they will be performed (needlessly) anyway. A good way around this is:

if( log.isDebugEnabled() )
    log.debug( "Entry number: " + i + " is " + String.valueOf( entry[ i ] ) );

PatternLayout

This class supports all sorts of interesting equivalent features to the C preprocessor like __FILENAME__ and __LINE__. However, these are implemented at runtime by log4j, require performing a stack crawl, and are generally too poor in performance to warrant using.

An alternative to scrapping the idea entirely is to lock out their use via a check for circumstances, assuming these can be detected, as noted earlier in this section.

The doc for this feature is found at: http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/PatternLayout.html


Web applications

log4j is particularly useful in web and distributed applications where using a debugger like the one in Eclipse is difficult or impossible. For Tomcat use, place log4j.properties where it will be copied down under the WEB-INF/classes subdirectory, for example, project-name/src.


log4j from Eclipse

Set up an Eclipse project and do some logging in it, for example.

package com.mycompany.pkg;

import org.apache.log4j.Logger;

public class MyClass
{
  private static final Logger log = Logger.getLogger( MyClass.class );
  .
  .
  .
  public void someMethod()
  {
    log.debug( "This is a message at DEBUG level in the log file" );
    .
    .
    .
}

Put log4j.properties directly into the src folder/directory of the project because to subsume it under src/properties or some other handy path requires more work.

Where to put log4j.properties?

In theory, this should be adjustable by the addition of

	import org.apache.log4j.PropertyConfigurator;
	.
	.
	.
	PropertyConfigurator.configure( "properties/log4j.properties" );
		

...but this does not seem to work unless you a) create a new folder at the same hierarchical level as src (let's call it properties for our example), then make it a "source" folder by right-clicking on it, choosing Build Path -> Use as Source Folder.

Put log4j.properties down under this new properties folder. Use refactoring (move) if you created it somewhere else first and want to relocate it. Inspect this picture of what I was doing one day along these lines. The logger went to the console and shows up as ERROR messages.

If log4j cannot find the properties file, a nasty gram will issue such as:


log4j:WARN No appenders could be found for logger (com.mycompany.pkg.MyClass).
log4j:WARN Please initialize the log4j system properly.

...and the logged message will (probably) come out anyway in the Eclipse console view, but you should set this up to work correctly (the point of this blurb).

Despite our message, we'll send this to the Eclipse console during our run. In consequence, set up log4j.properties thus. This is a good place to get started.

# The root logger is assigned priority level DEBUG and an appender named
# myAppender.
log4j.rootLogger=DEBUG,myAppender

# The appender's type specified as ConsoleAppender, i.e. log output to
# the Eclipse console. (Could have been FileAppender.)
log4j.appender.myAppender=org.apache.log4j.ConsoleAppender

# The appender is assigned a layout SimpleLayout. SimpleLayout will
# include only priority level of the log statement and the log statement
# itself in the log output.
log4j.appender.myAppender.layout=org.apache.log4j.SimpleLayout

Where to put log4j.properties (or log4j.xml): round 2

Especially since I've switched to using IntelliJ IDEA, this raises its head again just a little bit.

For configuration, there's a pecking order. Apparently, log4j2-test.xml is sought in the classpath before log4j2.xml. Hmmm... I guess the way to ensure that the first one isn't found is to put it into src/test/ somewhere because those paths don't get included bu the build (ordinarily).

The configuration file may be added just about anywhere, but if not added to an existing path already in classpath, then its location must be configured into classpath of the IDE. This is really bad. The less configuration there is, the better, say I.

I see a statement to the effect that if my project uses Maven to build, then put log4j configuration on the path src/main/resources (and, likely, log4j2-test.xml on src/test/resources). However, this seems to be disputed. Others say to put it at the root of the src folder. The problem is that there are many, knee-jerk Eclipse heads and Eclipse used to ignore proper Java pathing (preferring src/... to src/main/java/...). So, I think "the root of src" for IntelliJ IDEA and properly sourced Maven paths would be src/main/java. This should be the root they're talking of. But, that's not where I'd like it. Here are some links to this confusing discussion:

I put two files, log4j.xml and log4j-test.xml on src/main/resources and src/test/resources respectively. I find that the one for testing doesn't work. One answer said that I can only use a system property to differentiate, -Dlog4j.configuration=log4j[-test].xml.

Okay, I've sorted out all the nastiness of slf4j and log4j. It appears a) that slf4j doesn't play well with log4j2, so I stopped trying to use the newer version, b) I had to include the following dependencies in Maven. This consists of the latest slf4j and the latestf of log4j version 1 I can find without resorting to some alpha or beta stuff:

  <properties>
    <slf4j.version>1.7.7</slf4j.version>
    <log4j.version>1.2.17</log4j.version>
  </properties>
  .
  .
  .
  <dependencies>
    .
    .
    .
    <!-- log4j support for slf4j: -->
    <dependency>
      <groupId>org.slf4j</groupId>
      <artifactId>slf4j-log4j12</artifactId>
      <version>${slf4j.version}</version>
      <scope>test</scope>
    </dependency>
    <!-- slf4j proper: -->
    <dependency>
      <groupId>org.slf4j</groupId>
      <artifactId>slf4j-api</artifactId>
      <version>${slf4j.version}</version>
    </dependency>
    <!-- log4j proper: -->
    <dependency>
      <groupId>log4j</groupId>
      <artifactId>log4j</artifactId>
      <version>${log4j.version}</version>
    </dependency>
    .
    .
    .
  </dependencies>

...and here's what my log4j.xml file, which I'm placing on the path src/main/resources looks like. I've got more work to do on it because there's some brevity without sacrificing clarity I like to configure, but I haven't done that yet:

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration debug="true">

  <appender name="console" class="org.apache.log4j.ConsoleAppender">
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern"
             value="%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n" />
    </layout>
  </appender>

  <appender name="file" class="org.apache.log4j.RollingFileAppender">
    <param name="append" value="false" />
    <param name="maxFileSize" value="10MB" />
    <param name="maxBackupIndex" value="10" />
    <param name="file" value="${catalina.home}/logs/mdht-restlet.log" />
    <layout class="org.apache.log4j.PatternLayout">
      <param name="ConversionPattern"
             value="%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n" />
    </layout>
  </appender>

  <root>
    <level value="TRACE" />
    <appender-ref ref="console" />
    <appender-ref ref="file" />
  </root>

</log4j:configuration>

log4j.properties with support for JSF and Spring

I shamelessly ripped this off from the web for future use.

log4j.rootLogger=DEBUG,myAppender

log4j.appender.myAppender=org.apache.log4j.RollingFileAppender
log4j.appender.myAppender.file=/var/log/myapp.log
log4j.appender.myAppender.maxFileSize=10MB
log4j.appender.myAppender.maxBackupIndex=10
log4j.appender.myAppender.layout=org.apache.log4j.PatternLayout
log4j.appender.myAppender.layout.ConversionPattern=%5p | %d | %F:%L | %m%n

log4j.logger.com.acme=DEBUG
log4j.logger.org.springframework=DEBUG
log4j.logger.javax.faces=DEBUG
log4j.logger.org.apache.myfaces=DEBUG
log4j.logger.com.sun.faces=DEBUG

Java service wrapper

A service wrapper wraps around another program to allow it to live in a more useful context. For example, the Java service wrapper from Tanuki Software manages, among an array of useful solutions to problems, the logging of an application written in Java.

The Java service wrapper places an initial log line prefix prior to anything formally logged to log4j as specified in wrapper.conf. This can be confusing when attempting, without success, to tailor the lines logged to your log file. You quickly realize that there is a leftmost "column" over whose format you seemingly have no power. This is because it's defined in a different configuration file than log4j.properties, usually wrapper.conf.

See, primarily, http://wrapper.tanukisoftware.org/doc/english/introduction.html

wrapper.logfile.format

For example,

wrapper.logfile.format=LPTM

...yields

INFO | wrapper  | 2012/03/23 13:45:33.560 | INFO my message stuff...

You can turn lines logged into blank lines using

wrapper.logfile.format=

...or constrain the logfile to just that content you are trying to log via the usual log4j mechanisms:

wrapper.logfile.format=M

Changing level at runtime

It's possible, and simple, to change the logging level at runtime:

import org.apache.log4j.Level;
import org.apache.log4j.Logger;
...

{
  ...
  Logger root = Logger.getRootLogger();
  Level  level = Level.toLevel( "DEBUG" );

  root.setLevel( level );
  ...
}

Some links...

...on some topics.


A great example of a production properties file...

Please see important note on using ${catalina.home} here.

# This controls /var/log/tomcat6/catalina.out on our servers such that this file doesn't
# grow beyond 550Mb, rolls each day and only 5 days back are kept.
log4j.rootLogger=TRACE,console,tomcat,splunkable

# Rolling-file appender for Tomcat, goes to catalina.out. ----------------------------
log4j.appender.tomcat.Threshold=INFO
log4j.appender.tomcat=org.apache.log4j.DailyRollingFileAppender
log4j.appender.tomcat.DatePattern='.'yyy-MM-dd
log4j.appender.tomcat.File=${catalina.base}/logs/catalina.out
log4j.appender.tomcat.file.MaxFileSize=500Mb
log4j.appender.tomcat.file.MaxBackupIndex=5
log4j.appender.tomcat.layout=org.apache.log4j.PatternLayout
log4j.appender.tomcat.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

# Splunkable log ---------------------------------------------------------------------
log4j.appender.splunkable.Threshold=TRACE
log4j.appender.splunkable=org.apache.log4j.RollingFileAppender
log4j.appender.splunkable.File=${catalina.base}/logs/accountmgr.log
log4j.appender.splunkable.MaxFileSize=1Gb
log4j.appender.splunkable.MaxBackupIndex=7
log4j.appender.splunkable.layout=org.apache.log4j.PatternLayout
log4j.appender.splunkable.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}: %m%n

log4j.category.com.acme.web.uas.logging=TRACE,splunkable
log4j.additivity.com.acme.web.uas.logging=false

# This logs output to the Eclipse console when running in that mode. -----------------
log4j.appender.console.Threshold=TRACE
log4j.appender.console=org.apache.log4j.ConsoleAppender
log4j.appender.console.layout=org.apache.log4j.SimpleLayout
log4j.appender.console.Target=System.out
log4j.appender.console.layout=org.apache.log4j.PatternLayout
log4j.appender.console.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

## Legend ----------------------------------------------------------------------------
# Conversion-    What's printed?
#    specifier
# %d{ABSOLUTE}   hh:mm:ss,mmm
# %5p            one of { INFO, DEBUG, TRACE, WARN, ERROR }
# %c{1}          (simple) class name
# %L             line number in Java file
# -              a hyphen
# %m             caller-supplied message
# %n             platform-specific line separation character (\n)
#
# E.g.: 17:12:40,013 DEBUG MongoDB:145 - Initializing Morphia for use on accountdb

Errors encountered and solved

I went over a complex logging scheme, such as the one illustrated above, and afterward noticed that all my JUnit tests were prefixed with the following.


log4j:ERROR setFile(null,true) call failed.
java.io.FileNotFoundException: /logs/catalina.out (No such file or directory)
	at java.io.FileOutputStream.open(Native Method)
	at java.io.FileOutputStream.(FileOutputStream.java:212)
	at java.io.FileOutputStream.(FileOutputStream.java:136)
	at org.apache.log4j.FileAppender.setFile(FileAppender.java:294)
	at org.apache.log4j.FileAppender.activateOptions(FileAppender.java:165)
	at org.apache.log4j.DailyRollingFileAppender.activateOptions(DailyRollingFileAppender.java:223)
.
.
.

This turned out to be quite simple. When I was running my JUnit tests, the very explicit treatment of Tomcat and other logging I put into log4j.properties was asking Log4j to open files that didn't exist in the environment.

The solution was simply to put a separate copy of log4j.properties under the test subdirectory of my project (parallel to the origin one under the src subdirectory). The final result was something like:

log4j.rootLogger=TRACE,console
log4j.appender.console.Threshold=TRACE
log4j.appender.console=org.apache.log4j.ConsoleAppender
log4j.appender.console.layout=org.apache.log4j.SimpleLayout
log4j.appender.console.Target=System.out
log4j.appender.console.layout=org.apache.log4j.PatternLayout
log4j.appender.console.layout.ConversionPattern=%d{ABSOLUTE} %5p %c{1}:%L - %m%n

Locking when logging—performance considerations

See article, here.


Configuring log4j starting in v2

This is different from how it was done in previous versions.

import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.core.LoggerContext;
import org.apache.logging.log4j.core.config.Configuration;
import org.apache.logging.log4j.core.config.LoggerConfig;
.
.
.
  if( LOGGING )
  {
    // turn on logging to INFO level...
    LoggerContext ctx = ( LoggerContext ) LogManager.getContext( false );
    Configuration config = ctx.getConfiguration();
    LoggerConfig loggerConfig = config.getLoggerConfig( LogManager.ROOT_LOGGER_NAME );
    loggerConfig.setLevel( Level.INFO );
    ctx.updateLoggers();
 }
.
.
.

Log4j2

...doesn't recognize log4j.properties but XML, JSON and other formats. And the name is by default, log4j2. Here's a working sample:

<?xml version="1.0" encoding="UTF-8"?>
<Configuration xmlns="http://logging.apache.org/log4j/2.0/config">
  <Properties>
    <Property name="LEVEL">trace</Property> <!-- Change to info in production -->
    <Property name="log-path">/var/log/search/</Property>
    <Property name="logfile-size">1 GB</Property>
    <Property name="cda-feeder">cda-feeder</Property>

    <!-- The console pattern gives calling method name and line numbers (%L). E.g.:
    TRACE | 2015-09-17 10:15:02 | [main] logging.Log4j2Example (Log4j2Example.java:38) - This will be printed on trace
      -->
    <Property name="console-pattern">%d{ABSOLUTE} %5p %c{1}:%L - %m%n</Property>

    <!-- The file pattern is shorter and more static; other differences are due simply to RollingFileAppender. E.g.:
    10:15:02,987 TRACE Log4j2Example: This will be printed on trace
      -->
    <Property name="file-pattern">   %d{ABSOLUTE} %5p %c{1}: %m%n    </Property>
  </Properties>

  <Appenders>
    <Console name="console" target="SYSTEM_OUT">
      <PatternLayout pattern="%-5p | %d{yyyy-MM-dd HH:mm:ss} | [%t] %C{2} (%F:%L) - %m%n" />
    </Console>

    <RollingFile name="rollingfile"
                 fileName="${log-path}/${cda-feeder}.log"
                 filePattern="${log-path}/${cda-feeder}-%d{yyyy-MM-dd}-%i.log"
                 append="true">
      <PatternLayout pattern="${file-pattern}" />
      <Policies>
        <SizeBasedTriggeringPolicy size="${logfile-size}" />
      </Policies>
      <DefaultRolloverStrategy max="4" />
    </RollingFile>
  </Appenders>

  <Loggers>
    <Logger name="root" level="${LEVEL}" additivity="false">
      <appender-ref ref="rollingfile" level="${LEVEL}" />
    </Logger>

    <Root level="${LEVEL}" additivity="false">
      <AppenderRef ref="console" />
      <AppenderRef ref="rollingfile" />
    </Root>
  </Loggers>

</Configuration>

Logging sins...

A list of don'ts...

  1. Don't log sensitive information.
  2. Don't log too much (exhausting disk space).
  3. Don't log cryptic messages (like, "Operation failed.").
  4. Don't use a single log file.
  5. Don't choose incorrect log levels.
  6. FATAL for errors that cause the application to crash or fail to start.
    ERROR for technical issues that need to be resolved for proper functioning of the system.
    WARN for temporary problems or unexpected behavior that does not significantly hamper the functioning of the application.
    INFO for messages that describe what is happening in the application.
    DEBUG for messages that could be useful in debugging an issue.
    TRACE, like DEBUG, but for more detailed events.
  7. Don't crush performance with logging. Don't log during
    loops
    file I/O operations
    Bracket such code by a conditional like:
    if( logger.isTraceEnabled() )
      ...
    
  8. Don't log to the console (except episodically, like early on, during test runs, etc.).

Outputting package paths in log...

For a list of conversion specifiers to use in logback.xml, see LOGBack: Chapter 6: Layouts: PatternLayout.

For example, encoder pattern     <pattern>%-5level [%thread] %date{ISO8601} %F:%L - %msg%n</pattern>
will output log statements with only filenames (including extensions) like:

TRACE [Native-Transport-Requests-2] 2018-02-06 11:03:03,126 IndexQueryHandler:237 - process()
TRACE [Native-Transport-Requests-2] 2018-02-06 11:03:03,126 IndexQueryHandler:103 - processBatch()
TRACE [Native-Transport-Requests-2] 2018-02-06 11:03:03,126 IndexQueryHandler:222 - execute()
ERROR [Native-Transport-Requests-2] 2018-02-06 11:03:03,127 Message:625 - Unexpected exception during request

...whereas, pattern     <pattern>%-5level [%thread] %date{ISO8601} %logger{5}:%L - %msg%n</pattern>
will output log statements with package paths (identified only by their initials) like:

TRACE [Native-Transport-Requests-2] 2018-02-06 11:03:03,126 c.p.c.s.IndexQueryHandler:237 - process()
TRACE [Native-Transport-Requests-2] 2018-02-06 11:03:03,126 c.p.c.s.IndexQueryHandler:103 - processBatch()
TRACE [Native-Transport-Requests-2] 2018-02-06 11:03:03,126 c.p.c.s.IndexQueryHandler:222 - execute()
ERROR [Native-Transport-Requests-2] 2018-02-06 11:03:03,127 o.a.c.t.Message:625 - Unexpected exception during request

In the log immediately above, o.a.c.t.Message is an abbreviation for, org.apache.cassandra.transport.Message.class.


What does %-5level mean in a logging PatternLayout?

Consider %-5level at line 22 in the Java code below and line 15 in the XML.

package chapters.layouts;

import org.slf4j.LoggerFactory;

import ch.qos.logback.classic.Logger;
import ch.qos.logback.classic.LoggerContext;
import ch.qos.logback.classic.encoder.PatternLayoutEncoder;
import ch.qos.logback.classic.spi.ILoggingEvent;
import ch.qos.logback.core.ConsoleAppender;

public class PatternSample
{
  static public void main( String[] args ) throws Exception
  {
    Logger        rootLogger    = ( Logger ) LoggerFactory.getLogger( Logger.ROOT_LOGGER_NAME );
    LoggerContext loggerContext = rootLogger.getLoggerContext();
    // we are not interested in auto-configuration...
    loggerContext.reset();

    PatternLayoutEncoder encoder = new PatternLayoutEncoder();
    encoder.setContext( loggerContext );
    encoder.setPattern( "%-5level [%thread]: %message%n" );
    encoder.start();

    ConsoleAppender< ILoggingEvent > appender = new ConsoleAppender< ILoggingEvent >();
    appender.setContext( loggerContext );
    appender.setEncoder( encoder );
    appender.start();

    rootLogger.addAppender( appender );
    rootLogger.debug( "Message 1" );
    rootLogger.warn( "Message 2" );
  }
}
<appender name="SYSTEMLOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
  <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
    <level>INFO</level>
  </filter>
  <file>${cassandra.logdir}/system.log</file>
  <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
    <fileNamePattern>${cassandra.logdir}/system.log.%i.zip</fileNamePattern>
    <minIndex>1</minIndex>
    <maxIndex>20</maxIndex>
  </rollingPolicy>
  <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
    <maxFileSize>20MB</maxFileSize>
  </triggeringPolicy>
  <encoder>
    <pattern>%-5level [%thread] %date{ISO8601} %F:%L - %msg%n</pattern>
  </encoder>
</appender>

Per PatternLayout Class, the conversion specifier %-5level simply means the level of the logging event should be left justified to a width of five characters. The conversion specifier is actually %level. For a list of conversion specifiers, see LOGBack: Chapter 6: Layouts: PatternLayout.


Pattern layout in log4j.xml...

Here are some log4j layout ConversionPattern values and their effects (actual output forced by unit tests I've written for a product). The one marked below is my personal favorite, but it depends on what's being done, what's needed, etc.:

  • %d{yyyy-MM-dd HH:mm:ss} %-5p %c{1}:%L - %m%n : (no package path)

    2018-06-14 08:07:48 ERROR Patient:60 - Gender ZZZ must be one of { M, F, UN }

  • %d{yyyy-MM-dd HH:mm:ss} %-5p %c:%L - %m%n : (include package path)

    2018-06-14 08:11:59 ERROR com.etretatlogiciels.pojos.Patient:60 - Gender ZZZ must be one of { M, F, UN }

  • %d{yyyy-MM-dd HH:mm:ss} %-5p %c{1.} - %m%n: (abbreviated package path and no line number)

    2018-06-14 08:42:44 ERROR c.e.p.Patient - Gender ZZZ must be one of { M, F, UN }
    2018-06-14 09:31:29 WARN c.e.p.Address - Country Elbonia is not 2-letter abbreviation

  • %d{yyyy-MM-dd HH:mm:ss} %-5p %c - %m%n : (faster because no line number)

    2018-06-14 08:24:47 ERROR com.etretatlogiciels.pojos.Patient - Gender ZZZ must be one of { M, F, UN }

  • [%t] %-5p %c %x - %m%n : (with threadname, no timestamp)

    [main] ERROR com.etretatlogiciels.pojos.Patient - Gender ZZZ must be one of { M, F, UN }

  • [%15.15t] %-5p %30.30c %x - %m%n : (with justification and padding)

    [           main] ERROR om.etretatlogiciels.pojos.Patient - Gender ZZZ must be one of { M, F, UN }

Note that removing the line number reduces in theory the amount of time logging takes since it obviates it from using reflection to determine it. According to Apache documentation, the following conversion specifiers will cause log4j to work harder (and run slower) in order to furnish the information requested:

C Fully qualified name of logging class
F Java code filename
l Fully qualified methodname, source filename and line number
L Line number
M Methodname

While L is popular, since it's going to change a lot with bug fixes and refactoring, why put it out? It would really only be helpful in code that's too long and making lots of logging calls. Choosing wording carefully, and maybe adding an identifying code to logged statements would be even more useful than the line number if it came to that.


Tilde (~) and brackets in a stack trace...
DEBUG [MessagingService-Outgoing-/10.10.10.134-Gossip] 2018-01-30 09:20:15,181 OutboundTcpConnection.java:545 -
Unable to connect to /10.10.10.134
java.net.ConnectException: Connection refused (Connection refused)
  at java.net.PlainSocketImpl.socketConnect(Native Method) ~[na:1.8.0_151]
  at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350) ~[na:1.8.0_151]
  at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206) ~[na:1.8.0_151]
  at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188) ~[na:1.8.0_151]
  at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392) ~[na:1.8.0_151]
  at java.net.Socket.connect(Socket.java:589) ~[na:1.8.0_151]
  at sun.security.ssl.SSLSocketImpl.connect(SSLSocketImpl.java:673) ~[na:1.8.0_151]
  at sun.security.ssl.SSLSocketImpl.(SSLSocketImpl.java:451) ~[na:1.8.0_151]
  at sun.security.ssl.SSLSocketFactoryImpl.createSocket(SSLSocketFactoryImpl.java:137) ~[na:1.8.0_151]
  at org.apache.cassandra.security.SSLFactory.getSocket(SSLFactory.java:98) ~[cassandra-ss-index-plugin-3.11.0.13.jar:na]
  at org.apache.cassandra.net.OutboundTcpConnectionPool.newSocket(OutboundTcpConnectionPool.java:141) ~[cassandra-index-plugin-3.11.0.13.jar:na]
  at org.apache.cassandra.net.OutboundTcpConnectionPool.newSocket(OutboundTcpConnectionPool.java:132) ~[cassandra-index-plugin-3.11.0.13.jar:na]
  at org.apache.cassandra.net.OutboundTcpConnection.connect(OutboundTcpConnection.java:433) [cassandra-index-plugin-3.11.0.13.jar:na]
  at org.apache.cassandra.net.OutboundTcpConnection.run(OutboundTcpConnection.java:262) [cassandra-index-plugin-3.11.0.13.jar:na]

Before the JAR name in stack traces, there are tildes right before an opening square bracket. What does this mean?

At the end of each stack frame of the exception, a string consisting of the JAR file containing the relevant class followed by the "Implementation-Version" as found in that JAR's manifest will be added. If the information is uncertain, then the class packaging data will be preceded by a tilde, i.e. the '~' character.

logback and log4j go to great lengths to ensure that the class packaging information they display is correct. However, when they are unable to guarantee the absolute correctness of the information, then they will prefix the data with a tilde. Thus, it is theoretically possible for the printed class packaging information to differ from the real class packaging information.


Getting logging working (to a file) running JUnit from IntelliJ IDEA

This involves configuration in log4j.xml, that's going to hold for both production and testing, and pom.xml. First, $PROJECT_ROOT/src/main/resources/log4j.xml:

<?xml version="1.0" encoding="UTF-8" ?>
<!DOCTYPE log4j:configuration SYSTEM "log4j.dtd">
<log4j:configuration debug="true">

  <appender name="console" class="org.apache.log4j.ConsoleAppender">
    <layout class="org.apache.log4j.EnhancedPatternLayout">
      <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1.} - %m%n" />
    </layout>
  </appender>

  <!-- When running unit tests, ${catalina.home} evaluates to nothing, then
       ${catalina.home}/logs/mdht-restlet.log becomes /log/mdht-restlet.log,
       which doesn't exist. -->
  <appender name="file" class="org.apache.log4j.RollingFileAppender">
    <param name="append" value="false" />
    <param name="maxFileSize" value="10MB" />
    <param name="maxBackupIndex" value="10" />
    <param name="file" value="${catalina.home}/logs/mdht-restlet.log" />
    <layout class="org.apache.log4j.EnhancedPatternLayout">
      <param name="ConversionPattern" value="%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1.}:%L - %m%n" />
    </layout>
  </appender>

  <root>
    <level value="TRACE" />
    <appender-ref ref="console" />
    <appender-ref ref="file" />
  </root>
</log4j:configuration>

The note in the comment above explains that, just because I've configured log4j carefully to work in production (which in this case is Tomcat), doesn't mean it's going to work when running JUnit under IntelliJ IDEA. What's going to happen initially is this:

log4j:ERROR setFile(null,false) call failed.
java.io.FileNotFoundException: /logs/mdht-restlet.log (No such file or directory)

This is because, after evaluating ${catalina.home},/tt>/logs/mdht-restlet.log, what's left is /logs/mdht-restlet.log. Likely, that path does not exist or you do not have access to it (on Linux or Windows C:\).

The solution is to use the maven-surefire-plugin in your pom.xml. This can be used to set environment variables while running tests during your build and during execution of JUnit tests from the IDE. (I.e.: this might work also from Eclipse.)

First, however, using information from Echoing Maven property definitions using echoproperties, and running Maven from the command line, I find the following definitions that I might draw on to determine where, for testing and building, I could define ${catalina.home}. I decide to use project.build.directory as it looks very official and stable:

                          basedir=/home/russ/sandboxes/mdht-restlet.next_release.dev/code/mdht-restlet
maven.multiModuleProjectDirectory=/home/russ/sandboxes/mdht-restlet.next_release.dev/code/mdht-restlet
               project.artifactId=mdht-restlet
          project.build.directory=/home/russ/sandboxes/mdht-restlet.next_release.dev/code/mdht-restlet/target
    project.build.outputDirectory=/home/russ/sandboxes/mdht-restlet.next_release.dev/code/mdht-restlet/target/classes
    project.build.sourceDirectory=/home/russ/sandboxes/mdht-restlet.next_release.dev/code/mdht-restlet/src/main/java
project.build.testOutputDirectory=/home/russ/sandboxes/mdht-restlet.next_release.dev/code/mdht-restlet/target/test-classes
project.build.testSourceDirectory=/home/russ/sandboxes/mdht-restlet.next_release.dev/code/mdht-restlet/src/test/java
                     project.name=mdht-restlet
                         user.dir=/home/russ/sandboxes/mdht-restlet.next_release.dev/code/mdht-restlet

...and then use this to define ${catalina.home} in the maven-surefire-plugin:

<build>
  <plugins>
    ...
    <plugin>
      <groupId>org.apache.maven.plugins</groupId>
      <artifactId>maven-surefire-plugin</artifactId>
      <version>${maven-surefire-plugin.version}</version>
      <configuration>
        <systemPropertyVariables>
          <catalina.home>${project.build.directory}</catalina.home>
        </systemPropertyVariables>
      </configuration>
    </plugin>
    ...
  </plugins>
</build>

Finally, when I run tests, I see logging statements appear on the path /home/russ/sandboxes/mdht-restlet.next_release/code/mdht-restlet/target/logs/mdht-restlet.log.

Yes, after target is erased (each build), target/logs/mdht-restlet.log will be conveniently recreated as soon as it's written to by log4j.

This information came from the Apache Maven Project page, Using System Properties.


Fixing NumberFormatException in log4j.xml

If you see the following:

log4j: Class name: [org.apache.log4j.RollingFileAppender]
log4j:ERROR Category option "1." not a decimal integer.
java.lang.NumberFormatException: For input string: "1."
	at java.lang.NumberFormatException.forInputString(NumberFormatException.java:65)
...

...it's likely because your using org.apache.log4j.PatternLayout in log4j.xml (or log4j.properties):

<layout class="org.apache.log4j.PatternLayout">
  <param name="ConversionPattern"
         value="%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1.}:%L - %m%n" />
</layout>

PatternLayout doesn't support a %c value, what's gathered by %c{1.} above, in the pattern string. Use EnhancedPatternLayout instead.

<layout class="org.apache.log4j.EnhancedPatternLayout">
  <param name="ConversionPattern"
         value="%d{yyyy-MM-dd HH:mm:ss} %-5p %c{1.}:%L - %m%n" />
</layout>