Java Ninja Chronicles By Norris Shelton

Things I learned in the pursuit of code

In a previous logback blog entry Hibernate Logging (e.g. JBOSS logging) I showed how to send the JBoss logging to your logback logging configuration.

One thing kept bothering me. If you turned on showSql, these were not captured by your logging. I was fishing through the code and discovered why. If you turn on showSql, it actually sets a variable named logToStdout. Just as the name says, in the code, it logs to STDOUT.

if ( logToStdout ) {
	System.out.println( "Hibernate: " + statement );
}

This results in logging like the following:

Hibernate: insert into cam_affiliate (Channel_ID, Name, Affiliate_ID) values (?, ?, ?)

Logging Sql statements via Logback

A better way is to NOT set showSql to true, but to add the following logger to your Logback configuration.

<!-- Displays the Hibernate SQL statements in your log instead of STDOUT like showSql does-->
<logger name="org.hibernate.SQL" level="DEBUG"/>

This displays logging similar to:

2016-02-19 09:09:30|DEBUG|insert into cam_affiliate (Channel_ID, Name, Affiliate_ID) values (?, ?, ?) ||org.hibernate.engine.jdbc.spi.SqlStatementLogger:92 

February 19th, 2016

Posted In: hibernate, hibernate logging, Java, java ninja, Javaninja, jboss logging, jcl-over-slf4j, log4j-over-slf4j, logback, Logging, Logging configuration, slf4j

Leave a Comment

Logback link is the new logging standard. It is built upon the Simple Logging Facade For Java (SLF4J) API. This API allows you to code to a standard API, the easily switch out the implementation as you wish.

This blog entry will cover several examples of things that are common in a Logback configuration file.


Maven dependencies for Logback

Including the following Maven dependency will pull in Logback and the SLF4J API that it needs.

<dependency>
    <groupId>ch.qos.logback</groupId>
    <artifactId>logback-classic</artifactId>
    <version>${logback.version}</version>
</dependency>

I also like to combine all of my logging from dependent APIs into my logs as well. To do this, you need to ensure that any dependencies that have a dependency on commons-logging are excluded. An example is below:

<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-webmvc</artifactId>
    <exclusions>
        <exclusion>
            <artifactId>commons-logging</artifactId>
            <groupId>commons-logging</groupId>
        </exclusion>
    </exclusions>
</dependency>

If you do that, then you can pull in the SLF4J API that implements the commons-logging API, but funnels all of the log messages through the standard SLF4J API that can then log via Logback. This library is included via:

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>jcl-over-slf4j</artifactId>
    <version>${slf4j.version}</version>
</dependency>

The same can be done for Log4J.

<dependency>
    <groupId>org.slf4j</groupId>
    <artifactId>log4j-over-slf4j</artifactId>
    <version>${slf4j.version}</version>
</dependency>

Configuration file name and location

When Logback starts-up it looks for a file on the classpath named logback.xml. If you are using Maven, the file will normally be located in src/main/resources. If you have a separate test logging configuration, then you can place a file named logback-test.xml in src/test/resources. Logback looks for the test file first and will use that configuration in-lieu of the regular logback configuration file.


Basic configuration file attributes

The basic logback configuration file is enclosed by an configuration element.

<configuration>
...
</configuration>

The configuration element has several attributes.

  • debug – instructs Logback to dump status data. This does NOT affect any logging levels.
    <configuration debug="true">
    ...
    </configuration>
    
  • scan – instructs Logback to scan for changes in it’s configuration file and automatically load the new configuration. By default, Logback scans the configuration file for changes once every minute. To change how often the configuration file is scanned for changes, also include the scanPeriod.
    <configuration scan="true">
    ...
    </configuration>
    
  • scanPeriod – this can be used in conjunction with scan and modifies how often the Logback configuration file is scanned for changes. Every 30 seconds in this case. Valid units of measure are milliseconds, seconds, minutes, hours. Milliseconds is assumed if no unit of time is specified.
    <configuration scan="true" scanPeriod="30 seconds">
    ...
    </configuration>
    

Logging components

Logback configuration files are mainly composed of two things, appender, root and logger elements.

Appenders

Appender elements define the various logging targets. Common appenders are:

  • ConsoleAppender – this logs to the system console.
  • FileAppender – this logs to a file.
  • RollingFileAppender – this logs to a file and then rolls to an archive file by some scheme. Common examples are daily and by file size.
  • SMTPAppender – this logs statements to an email and mails them to a recipient(s).

Roots

Root elements define which messages will be sent to the enclosed appenders. You can have one more root elements and they can contain one or more appender(s). Here are some examples:

This says to log messages to the appender identified by CONSOLE at the INFO level or higher.

<root level="INFO">
    <appender-ref ref="CONSOLE"/>
</root>

This says to log messages to the appender identified by ROLLING_FILE and SMTP at the WARN or higher.

<root level="WARN">
    <appender-ref ref="ROLLING_FILE"/>
    <appender-ref ref="SMTP"/>
</root>

Loggers

Logger elements offer a way to override what is logged via root elements or appender elements. Take the following example.

<logger name="com.javaninja" level="INFO"/>

<root level="WARN">
    <appender-ref ref="ROLLING_FILE"/>
    <appender-ref ref="SMTP"/>
</root>

This says that ROLLING_FILE and SMTP should show log messages at the WARN level or higher. However, the logger element says that anything that is associated with a logger instance that has a value of com.javaninja or more should be logged at the INFO level, regardless of the root level.

You can also specify an appender within a logger

<logger name="com.javaninja" level="INFO">
    <appender-ref ref="ROLLING_FILE"/>
</logger>

<root level="WARN">
    <appender-ref ref="ROLLING_FILE"/>
    <appender-ref ref="SMTP"/>
</root>

This says to set the logging level of com.javaninja to INFO, but only for the ROLLING_FILE appender. This one I have never actually used, but thought it would be good to show the flexibility.


Logging pattern

The logging pattern determines what is logged for your statements. This is a good time to include things like the application that is logging and the hostname that you are actually running on.

This is a logging pattern that I like;

%d{yyyy-MM-dd HH:mm:ss}|${HOSTNAME}|my-app|%-5level|%msg ||%class:%line %n

This pattern is pipe-delimited (|). The various items being logged are as follows:

  • %d{yyyy-MM-dd HH:mm:ss} – this logs the date in the specified format.
  • ${HOSTNAME} – this logs the hostname that the application is running on.
  • my-app – this a name that I use to identify my application. This is useful if I’m running multiple apps on the same machine and they are logging to the same log or to the console. Another way to do this is via %contextName. This logs the value of the logging contextName. The default value is default. This value is set via
    <contextName>my-app</contextName>
    
  • %-5level – this displays the logging level (e.g. debug, info, warn or error. The -5 allocated 5 characters for the field, even if it only takes 4 characters.
  • %msg – this is the actual message being logged.
  • %class:%line – this logs the name of the class, including the full package, and the line number in the class that logged the message. No more text searching for a message to see where it came from and having to make a guess when the same message is logged in more than one place.
  • %n – this outputs a newline character at the end of the line.

Logging to Console

Logging is done via appenders. An example console appender is below.

<configuration>
	<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
		<encoder>
			<pattern>%d{yyyy-MM-dd HH:mm:ss}|${HOSTNAME}|%contextName|%-5level|%msg ||%class:%line %n</pattern>
		</encoder>
	</appender>
	<!-- the console defaults to INFO level-->
	<root level="INFO">
		<appender-ref ref="CONSOLE"/>
	</root>
</configuration>

Here I am saying to log the information with the specified logging pattern and I want the root logging level to be INFO. I then place the appender reference containing the reference to the CONSOLE within it. This says that all logging messages that are severity INFO and higher will be logged. Any log messages below INFO will not be logged.


Writing to a file

FileAppender

Writing to a file is as simple as using the FileAppender

<configuration>
  <appender name="FILE" class="ch.qos.logback.core.FileAppender">
    <file>javaninja.log</file>
    <append>true</append>
    <encoder>
      <pattern>%d{yyyy-MM-dd HH:mm:ss}|${HOSTNAME}|%contextName|%-5level|%msg ||%class:%line %n</pattern>
    </encoder>
  </appender>
        
  <root level="INFO">
    <appender-ref ref="FILE" />
  </root>
</configuration>

The file element indicates the current logging file name and location. With that said, rarely do you ever have a real need to write to a huge file that just grows and grows and grows. The more likely usage is a RollingFileAppender. This is a file that archives it’s older contents according to some schedule. By day and by size are the two most common schedules.

Personally, I hate when a file is rolled by size. All that does is force a developer to wade through files to determine which one has the logging that I need. Generally, you see this when there is too much being logged. I prefer to filter the log messages appropriately, then roll the file by day.

RollingFileAppender

A RollingFileAppender must have a RollingPolicy (what) and a Triggering policy (when). Generally, with time-based triggering policies, the file doesn’t change by the time, but by logging events. When a logging event is received, a check is made to determine if rolling should occur. In common usage, you will never see the difference.

I like to use TimeBasedRollingPolicy, which performs both of these functions. The TimeBasedRollingPolicy rolling schedule is inferred from the value of the fileNamePattern enclosed within it’s tag. Meaning, if you give a date pattern that includes the day, then it will roll per day. If you give it a date pattern that contains the year and month, it will rotate monthly. If you use a date/time pattern that only includes the hour, the file will rotate per hour. There is also a maxHistory element that indicates the number of archive files to keep. It will automatically delete the archive files and any enclosing directories as defined by the fileNamePattern

<configuration>
    <appender name="ROLLING_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>/opt/server/log/javaninja.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- daily rollover -->
            <fileNamePattern>/opt/server/log/archive/javaninja.%d{yyyy-MM-dd}.log</fileNamePattern>
            <!-- keep 90 days' worth of history -->
            <maxHistory>90</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss}|${HOSTNAME}|%contextName|%-5level|%msg ||%class:%line %n</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="ROLLING_FILE" />
    </root>
</configuration>

The active logging file will be kept in /opt/server/log and it will be named javaninja.log. When the first log message of a new day is logged, the contents of that file will be moved to /opt/server/log/archive and the date will be added to the file name. On the 91st day and thereafter, the oldest file will be deleted.

SMTPAppender

Sending an email is something that I like to do with exceptions in production. It is a fast way to surface problems and catch them as they happen. The SMTPAppender takes the normal values that you would expect to send an email.

  • SMTPHost – This is the location of the SMTP Host. It is common for it to be localhost, but it could be one common server.
  • To – to whom should the email be sent. This element can be repeated if there are multiple mail account recipients.
  • From – this is the value of the email sender. It usually doesn’t have to be a real account. If your SMTP server requires authentication, then it may need to be a real account and include a password.
  • Subject – the subject value of the email. Variable substitution can be used. I usually follow the pattern in the Logback documentation and include the host that the log message came from, the name of the logger (package and class) and the message. If you have multiple apps on that host, it may be useful to put in an indicator to note the app that the messages originated from.

You can use the patternLayout which takes a pattern just like the other appenders, but I prefer the HTMLLayout. With this, comes the caveat, that the data will be included in an HTML table. The layout will automatically put each specifier (logging item) into it’s own column. This means that you should not include separators. If you do, then the separators will be placed in their own table column and will waste space. Generally what I do is use my usual pattern, but remove any pipe “|” characters, spaces and new lines.

You can also use the cyclicBufferTracker to batch emails. This is useful if you have a high volume of errors and want to receive them 5, 10, 100 or any arbitrary number of messages at a time. This will cause the messages to be held until the bufferSize is exceeded, then all of the held messages will be sent in the same email. I prefer to use as small a number as possible because if you have it set too high, let’s say 100, then the first block of messages may be held for a long time until the threshold is reached.

<configuration>
	<appender name="SMTP" class="ch.qos.logback.classic.net.SMTPAppender">
		<SMTPHost>localhost</SMTPHost>
		<to>norris.shelton@javaninja.com</to>
		<from>errors@javaninja.com</from>
		<subject>${HOSTNAME} - %logger{20} - %m</subject>
		<layout class="ch.qos.logback.classic.html.HTMLLayout">
			<!--
                NOTE: HTML layout generates a separate column for each specifier.
                Adding separators will cause columns with only the separator
            -->
			<Pattern>%d{yyyy-MM-dd HH:mm:ss}${HOSTNAME}%contextName%-5level%msg%class:%line</Pattern>
		</layout>
		<cyclicBufferTracker class="ch.qos.logback.core.spi.CyclicBufferTracker">
			<!-- hold the email and send 5 log entry per email -->
			<bufferSize>5</bufferSize>
		</cyclicBufferTracker>
	</appender>

</configuration>

Conclusion

This covers most of the common things that are possible in Logback. There are tons of options to use for the configuration that accomplish pretty much anything that you would need to do in a logging framework.

February 4th, 2016

Posted In: java ninja, Javaninja, jcl-over-slf4j, log4j-over-slf4j, logback, Logging, Logging configuration

Leave a Comment

A common logging configuration is a log file per day. Building off of Logback Configuration File Change, let’s determine what it would take to also add a daily rolling file. How do you do this with logback?

In this example, I turned on the automatic scanning of the logback configuration file and set it to check every 5 minutes. This is a good compromise between being able to change the logging configuration on the file and also preventing increased load on the production file system.

I also created several variables to make customizing the configuration to individual developers workstation’s easy.

In this example, I used a TimeBasedRollingAppender to roll the file once per day. Logback keeps 30 days of files around and doesn’t use compression. To enable compression, change the fileNamePattern inside the rollingPolicy to end in .gz or .zip instead of .log.

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="5 minutes">

    <property name="contextName" value="bonus-services"/>
    <!--
        The directory that the log files will be created in.  If the directory does not exist, Logback will give an
        error.  Logback will continue to log to the console, but there will be no log created.  Some developers will
        prefer this way so that they can see the files in the console, but don't have to worry about them on their local
        machines.

        To create a symbolic link (/opt/tomcat) to your actual tomcat installation:
        sudo ln -s ~/apache-tomcat-8.0.28 /opt/tomcat
    -->
    <property name="loggingDir" value="/opt/tomcat/logs"/>
    <property name="encoderPattern"
              value="%d{HH:mm:ss.SSS}|%-5level|${HOSTNAME}|${contextName}|%msg ||%class:%line %xException{full} %n"/>


    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <!-- encoders are assigned the type ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
        <encoder>
            <pattern>${encoderPattern}</pattern>
        </encoder>
    </appender>
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${loggingDir}/${contextName}.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- daily rollover -->
            <fileNamePattern>${contextName}.%d{yyyy-MM-dd}.log</fileNamePattern>

            <!-- keep 30 days' worth of history -->
            <maxHistory>30</maxHistory>
        </rollingPolicy>

        <encoder>
            <pattern>${encoderPattern}</pattern>
        </encoder>
    </appender>

    <logger name="com.cdi" level="INFO"/>
    <!-- Show info on rest calls -->
    <logger name="org.springframework.web.client" level="DEBUG"/>
    <logger name="org.springframework.http.converter" level="DEBUG"/>

    <root level="WARN">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="FILE"/>
    </root>
</configuration>

December 15th, 2015

Posted In: java ninja, Javaninja, logback

Leave a Comment

I have been using Logback for a while. It’s pretty easy to use and it’s fairly easy to configure. I noticed that I had some warning messages in my log file.

10:51:04,532 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback.groovy]
10:51:04,532 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Could NOT find resource [logback-test.xml]
10:51:04,532 |-INFO in ch.qos.logback.classic.LoggerContext[default] - Found resource [logback.xml] at [file:/Users/norrisshelton/IdeaProjects/gsi-adapter/gsi-adapter-services/target/gsi-services/WEB-INF/classes/logback.xml]
10:51:04,578 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - debug attribute not set
10:51:04,586 |-INFO in ReconfigureOnChangeFilter{invocationCounter=0} - Will scan for changes in [[/Users/norrisshelton/IdeaProjects/gsi-adapter/gsi-adapter-services/target/gsi-services/WEB-INF/classes/logback.xml]] every 60 seconds. 
10:51:04,586 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - Adding ReconfigureOnChangeFilter as a turbo filter
10:51:04,589 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - About to instantiate appender of type [ch.qos.logback.core.ConsoleAppender]
10:51:04,593 |-INFO in ch.qos.logback.core.joran.action.AppenderAction - Naming appender as [STDOUT]
10:51:04,649 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - This appender no longer admits a layout as a sub-component, set an encoder instead.
10:51:04,649 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - To ensure compatibility, wrapping your layout in LayoutWrappingEncoder.
10:51:04,649 |-WARN in ch.qos.logback.core.ConsoleAppender[STDOUT] - See also http://logback.qos.ch/codes.html#layoutInsteadOfEncoder for details
10:51:04,650 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [com.cdi] to DEBUG
10:51:04,650 |-INFO in ch.qos.logback.classic.joran.action.LoggerAction - Setting level of logger [org.springframework.web.client.RestTemplate] to DEBUG
10:51:04,650 |-INFO in ch.qos.logback.classic.joran.action.RootLoggerAction - Setting level of ROOT logger to WARN
10:51:04,650 |-INFO in ch.qos.logback.core.joran.action.AppenderRefAction - Attaching appender named [STDOUT] to Logger[ROOT]
10:51:04,651 |-INFO in ch.qos.logback.classic.joran.action.ConfigurationAction - End of configuration.
10:51:04,652 |-INFO in ch.qos.logback.classic.joran.JoranConfigurator@c28ccfa - Registering current configuration as safe fallback point

I checked and discovered that the logging configuration had changed. An example is it used to look like:

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true">
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%d{HH:mm:ss.SSS}|%-5level|${HOSTNAME}|cdi-services|%msg ||%class:%line %xException{full} %n</Pattern>
        </layout>
    </appender>

    <logger name="com.cdi" level="DEBUG"/>
    <!-- Show info on rest calls -->
    <logger name="org.springframework.web.client.RestTemplate" level="DEBUG"/>

    <root level="WARN">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

I was getting messages about layout should be wrapped in an encoder. After some tinkering, I arrived at the following:

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true">
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <!-- encoders are assigned the type ch.qos.logback.classic.encoder.PatternLayoutEncoder by default -->
        <encoder>
            <pattern>%d{HH:mm:ss.SSS}|%-5level|${HOSTNAME}|cdi-services|%msg ||%class:%line %xException{full} %n</pattern>
        </encoder>
    </appender>

    <logger name="com.cdi" level="DEBUG"/>
    <!-- Show info on rest calls -->
    <logger name="org.springframework.web.client.RestTemplate" level="DEBUG"/>

    <root level="WARN">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

The gist of it is that the appender now has an encoder instead of a layout. When the correct changes are made to the configuration file, there is no longer any start-up logging from LogBack in the logs, but you will see that the new logging format is being honored.

A little note is that I leave a space after msg% to help with the wrapping when the lines are too long.

|%msg |

August 11th, 2015

Posted In: Java, java ninja, Javaninja, logback, Logging, Logging configuration

One Comment

I was getting the following debug logging, even though my logging config said info and above.

15:14:02.541|DEBUG|RdbmsOperation with SQL [p_select_validate_pin_person_token] compiled||org.springframework.jdbc.object.RdbmsOperation:344
15:14:02.541|DEBUG|Compiled stored procedure. Call string is [{call p_select_validate_sso_person_token(?, ?)}]||org.springframework.jdbc.object.SqlCall:154
15:14:02.541|DEBUG|RdbmsOperation with SQL [p_select_validate_sso_person_token] compiled||org.springframework.jdbc.object.RdbmsOperation:344
15:14:02.542|DEBUG|Compiled stored procedure. Call string is [{call p_delete_truncate(?)}]||org.springframework.jdbc.object.SqlCall:154
15:14:02.542|DEBUG|RdbmsOperation with SQL [p_delete_truncate] compiled||org.springframework.jdbc.object.RdbmsOperation:344
15:14:02.543|DEBUG|Compiled stored procedure. Call string is [{call p_update_setting_inprogress(?)}]||org.springframework.jdbc.object.SqlCall:154

During my research, I learned that Hibernate is logged via JBoss Logging. It used to require a properties file that denoted which logging implementation to use. It now will try to use several logging frameworks, such as commons-logging, log4j and logback. I use Logback.

One common problem is that if you are pulling in lots of dependent libraries, it isn’t uncommon to have multiple logging APIs preset. That was the case that I had.

I checked my dependencies and discovered that I had libraries for:

  • logback-classic – logback is my preferred logging framework.
  • commons-logging – this is the culprit. The JBoss logging API is finding this framework, but isn’t finding a configuration file so everything is being logged.
  • jboss-logging – this is the jboss logging api and is required
  • log4j-over-slf4j – this is the slf4j implementation of the log4j api. In essence, hijacking log4j and funnelling the log4j logging events through slf4j.

To fix this, I had to find every Maven dependency that has a transitive dependency on commons-logging and exclude commons-logging. An example of something that had commons-logging as a transitive dependency was spring-webmvc. I modified the dependency by adding exclusions.

        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-webmvc</artifactId>
            <exclusions>
                <exclusion>
                    <artifactId>commons-logging</artifactId>
                    <groupId>commons-logging</groupId>
                </exclusion>
            </exclusions>
        </dependency>

Once I removed all commons-logging transitive dependencies, I had to provide a suitable substitute. This is where another SLF4j dependency comes in handy. This is a SLF4J implementation of the commons-logging api which funnels all of the commons-logging events to my slf4J implementation.

        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>jcl-over-slf4j</artifactId>
            <version>1.7.7</version>
        </dependency>

December 30th, 2014

Posted In: hibernate, hibernate logging, java ninja, Javaninja, jboss, jboss logging, jcl-over-slf4j, log4j-over-slf4j, logback, Logging, slf4j

Tags: , , , , , , , , , ,

2 Comments

We wanted to default logging of all messages to warning and above for libraries that we used. We wanted our code to be logged at the info level and above. There was one specific library class that was logging a warning message that was causing confusion to the junior members of the team. Here is what my logback.xml contains.

  • Line 9 – log classes under the com.cdi package at the info level and above
  • Line 11 – log this specific class at the error level and above
  • Line 13 – default logging of the standard out appender to warnings and above
<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true">
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%d{HH:mm:ss.SSS}|%-5level|%msg||%class:%line %xException{full} %n</Pattern>
        </layout>
    </appender>

    <logger name="com.cdi" level="INFO"/>
    <!--Don't show the warning message for no ViewResolvers-->
    <logger name="org.springframework.web.servlet.view.ContentNegotiatingViewResolver" level="ERROR"/>

    <root level="WARN">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

December 30th, 2014

Posted In: appender, appender configuration, java ninja, Javaninja, logback, Logging, Logging configuration, slf4j

Tags: , , , , , , ,

Leave a Comment

Logging is needed, but all of the different frameworks makes this a pain. You are trying to research a problem and you have to bounce from log to log to research it.

SLF4J has bridge implementations that delegate to SLF4J APIs for commons-logging, log4j and even jdk logging.

You need to include the dependency for the logging API that you want to hijack as provided so they will not be packaged, then include the SLF4J bridge api. Repeat for each logging API you want to hijack, then include a SLF4J logging implementation, then away you go.

Here is how to hijack log4j

        <!--hijack log4j-->
        <!--NOTE Saying it is provided so it will not be packaged in my builds if a dependency is using it-->
        <dependency>
            <groupId>log4j</groupId>
            <artifactId>log4j</artifactId>
            <version>1.2.16</version>
            <scope>provided</scope>
        </dependency>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>log4j-over-slf4j</artifactId>
            <version>${slf4j.version}</version>
            <scope>provided</scope>
        </dependency>

There are 3 strains of log4j (1.2, 1.3 & 2.0). None are compatible with any of the other. Luckily, only 1.2 is commonly used.

Here is how to hijack commons-logging

        <!--hijack commons logging-->
        <dependency>
            <groupId>commons-logging</groupId>
            <artifactId>commons-logging</artifactId>
            <version>1.1.1</version>
            <scope>provided</scope>
        </dependency>
        <dependency>
            <groupId>org.slf4j</groupId>
            <artifactId>jcl-over-slf4j</artifactId>
            <version>${slf4j.version}</version>
        </dependency>

There is also a jcl104-over-slf4j for commons-logging 1.0.x. I tried to be slick and include that on a project and it got ugly. Those versions of the commons-logging API must not be compatible.

I usually don’t hijack the jdk logging because I rarely encounter it.

All that is remaining is to include a SLF4J implementation. There is one for commons-logging and log4j, but my preferred solution is logback.

        <!-- LogBack -->
        <dependency>
            <groupId>ch.qos.logback</groupId>
            <artifactId>logback-classic</artifactId>
            <version>0.9.27</version>
        </dependency>

This is what works for me, but I see where there could be problems. The logging APIs that I am hijacking are in the compile classpath, but not in the deploy classpath. It could be possible to use Maven exclusions to totally strip out the artifacts, but you must put an exclusion on each dependency that uses the artifact. Good luck keeping up with that. They are supposed to fix this in maven 3.1

February 3rd, 2011

Posted In: Java, logback, slf4j

Tags: , , , , , , , ,

Leave a Comment

A needed feature of logging is to be able to identify which user caused the line of logging in the log file. Logback implements SLF4j and allows for tagging each log entry with information that the developer deems useful. Create a filter class to add the value to the MDC:

package com.bhsi;


import com.bhsi.dao.user.UserUtil;
import org.apache.commons.lang.StringUtils;
import org.slf4j.MDC;

import javax.servlet.Filter;
import javax.servlet.FilterChain;
import javax.servlet.FilterConfig;
import javax.servlet.ServletException;
import javax.servlet.ServletRequest;
import javax.servlet.ServletResponse;
import javax.servlet.http.HttpServletRequest;
import java.io.IOException;


/** @author Norris Shelton */
public class UserLoggingFilter implements Filter {

    private final String -- USER_KEY = "userId";

    /**
     * Called by the web container to indicate to a filter that it is being placed into service. The servlet container
     * calls the init method exactly once after instantiating the filter. The init method must complete successfully before
     * the filter is asked to do any filtering work. <br><br>
     * <p/>
     * The web container cannot place the filter into service if the init method either<br> 1.Throws a ServletException
     * <br> 2.Does not return within a time period defined by the web container
     */
    public void init(FilterConfig filterConfig) throws ServletException {
        //To change body of implemented methods use File | Settings | File Templates.
    }

    /**
     * The <code>doFilter</code> method of the Filter is called by the container each time a request/response pair is
     * passed through the chain due to a client request for a resource at the end of the chain. The FilterChain passed in
     * to this method allows the Filter to pass on the request and response to the next entity in the chain.<p> A typical
     * implementation of this method would follow the following pattern:- <br> 1. Examine the request<br> 2. Optionally
     * wrap the request object with a custom implementation to filter content or headers for input filtering <br> 3.
     * Optionally wrap the response object with a custom implementation to filter content or headers for output filtering
     * <br> 4. a) <strong>Either</strong> invoke the next entity in the chain using the FilterChain object
     * (<code>chain.doFilter()</code>), <br> * 4. b) <strong>or</strong> not pass on the request/response pair to the next
     * entity in the filter chain to block the request processing<br> * 5. Directly set headers on the response after
     * invocation of the next entity in the filter chain.
     */
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
    throws IOException, ServletException {
        boolean successfulRegistration = false;

        HttpServletRequest req = (HttpServletRequest) request;

        successfulRegistration = registerUsername(req.getRemoteUser());

        try {
            chain.doFilter(request, response);
        } finally {
            if (successfulRegistration) {
                MDC.remove(-- USER_KEY);
            }
        }

    }

    /**
     * Register the user in the MDC under -- USER_KEY.
     * @param userId the id of the user
     * @return true id the user was successfully registered
     */
    private boolean registerUsername(String userId) {
        boolean isRegisterUser = false;
        if (StringUtils.isNotBlank(userId)) {
            MDC.put(-- USER_KEY, UserUtil.getSimpleUserName(userId));
            isRegisterUser = true;
        }
        return isRegisterUser;
    }


    /**
     * Called by the web container to indicate to a filter that it is being taken out of service. This method is only
     * called once all threads within the filter's doFilter method have exited or after a timeout period has passed. After
     * the web container calls this method, it will not call the doFilter method again on this instance of the filter.
     * <br><br>
     * <p/>
     * This method gives the filter an opportunity to clean up any resources that are being held (for example, memory, file
     * handles, threads) and make sure that any persistent state is synchronized with the filter's current state in
     * memory.
     */
    public void destroy() {
        //To change body of implemented methods use File | Settings | File Templates.
    }
}

Add the filter class to the web.xml

    <filter>
        <filter-name>UserLoggingFilter</filter-name>
        <filter-class>com.bhsi.UserLoggingFilter</filter-class>
    </filter>
    <filter-mapping>
        <filter-name>UserLoggingFilter</filter-name>
        <url-pattern>/*</url-pattern>
    </filter-mapping>

Modify the logback pattern to use the value added by the filter to the current logging thread.

<configuration>
    <!--
        WARN or higher goes to stdout (catalina.out)
    -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>WARN</level>
        </filter>
        <encoder>
            <Pattern>%d{yyyy-MM-dd HH:mm:ss} intranet-templating:%X{userId}|%-5level-%msg %class.%method:%line %xException{full} %n</Pattern>
        </encoder>
    </appender>
    <!--
        INFO or higher goes to the log file that is in the tomcat logs directory.
        The files are rolled daily to the tomcat/logs/intranet-templating. 
    -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>/opt/vignette/software/tomcat/logs/intranet-templating.log</file>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <if condition='property("HOSTNAME").contains("309")'>
                <then>
                    <level>DEBUG</level>
                </then>
                <else>
                    <level>INFO</level>
                </else>
            </if>
        </filter>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>/opt/vignette/software/tomcat/logs/intranet-templating/intranet-templating.%d{yyyy-MM-dd}.log</fileNamePattern>
        </rollingPolicy>
        <encoder>
            <Pattern>%d{yyyy-MM-dd HH:mm:ss}|%X{userId}|%-5level-%msg %class.%method:%line %xException{full} %n</Pattern>
        </encoder>
    </appender>

    <logger name="org.hibernate" level="WARN"/>
    <!--<logger name="org.springframework" level="INFO"/>-->
    <logger name="org.apache.commons" level="INFO"/>
    <logger name="org.apache.velocity" level="INFO"/>
    <logger name="org.displaytag" level="INFO"/>
    <logger name="org.apache.axis" level="INFO"/>
    <root level="DEBUG">
        <appender-ref ref="FILE"/>
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

December 6th, 2010

Posted In: logback

Leave a Comment

This is such a common problem. You want to have one file that you deploy everywhere, but you want it to behave differently based upon where you deploy it. An example is you want logback to log debug in dev, but info in production. This is easy to do with the conditional processing. Check out logback conditional processing for other options.

<configuration>
    <!--
        WARN or higher goes to stdout (catalina.out)
    -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>WARN</level>
        </filter>
        <encoder>
            <Pattern>%d{yyyy-MM-dd HH:mm:ss} intranet-templating:%X{userId}|%-5level-%msg %class.%method:%line %xException{full} %n</Pattern>
        </encoder>
    </appender>
    <!--
        INFO or higher goes to the log file that is in the tomcat logs directory.
        The files are rolled daily to the tomcat/logs/intranet-templating. 
    -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>/opt/vignette/software/tomcat/logs/intranet-templating.log</file>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <if condition='property("HOSTNAME").contains("309")'>
                <then>
                    <level>DEBUG</level>
                </then>
                <else>
                    <level>INFO</level>
                </else>
            </if>
        </filter>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>/opt/vignette/software/tomcat/logs/intranet-templating/intranet-templating.%d{yyyy-MM-dd}.log</fileNamePattern>
        </rollingPolicy>
        <encoder>
            <Pattern>%d{yyyy-MM-dd HH:mm:ss}|%X{userId}|%-5level-%msg %class.%method:%line %xException{full} %n</Pattern>
        </encoder>
    </appender>

    <logger name="org.hibernate" level="WARN"/>
    <!--<logger name="org.springframework" level="INFO"/>-->
    <logger name="org.apache.commons" level="INFO"/>
    <logger name="org.apache.velocity" level="INFO"/>
    <logger name="org.displaytag" level="INFO"/>
    <logger name="org.apache.axis" level="INFO"/>
    <root level="DEBUG">
        <appender-ref ref="FILE"/>
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

December 6th, 2010

Posted In: logback

Leave a Comment

Maven has two places for configuration files that need to be deployed to the classpath. You need to place a logback configuration file in both.

The main logback configuration file is named logback.xml and should be in src/main/resources of your maven project.

<configuration>
    <!--
        WARN or higher goes to stdout (catalina.out)
    -->
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>WARN</level>
        </filter>
        <encoder>
            <Pattern>%d{yyyy-MM-dd HH:mm:ss} intranet-templating:%X{userId}|%-5level-%msg %class.%method:%line %xException{full} %n</Pattern>
        </encoder>
    </appender>
    <!--
        INFO or higher goes to the log file that is in the tomcat logs directory.
        The files are rolled daily to the tomcat/logs/intranet-templating. 
    -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>/opt/vignette/software/tomcat/logs/intranet-templating.log</file>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <if condition='property("HOSTNAME").contains("309")'>
                <then>
                    <level>DEBUG</level>
                </then>
                <else>
                    <level>INFO</level>
                </else>
            </if>
        </filter>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>/opt/vignette/software/tomcat/logs/intranet-templating/intranet-templating.%d{yyyy-MM-dd}.log</fileNamePattern>
        </rollingPolicy>
        <encoder>
            <Pattern>%d{yyyy-MM-dd HH:mm:ss}|%X{userId}|%-5level-%msg %class.%method:%line %xException{full} %n</Pattern>
        </encoder>
    </appender>

    <logger name="org.hibernate" level="WARN"/>
    <!--<logger name="org.springframework" level="INFO"/>-->
    <logger name="org.apache.commons" level="INFO"/>
    <logger name="org.apache.velocity" level="INFO"/>
    <logger name="org.displaytag" level="INFO"/>
    <logger name="org.apache.axis" level="INFO"/>
    <root level="DEBUG">
        <appender-ref ref="FILE"/>
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="NORRIS-EMAIL"/>
    </root>
</configuration>

The test logback configuration file is named logback-test.xml and should be in src/test/resources of your maven project. If logback sees both files (e.g. test build), then the -test file will be the logback configurations.

<configuration>
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <Pattern>%d{yyyy-MM-dd HH:mm:ss} %X{userId} %-5level - %msg %class.%method:%line %xException{full} %n </Pattern>
        </encoder>
    </appender>

    <!--default to logging info-->
    <root level="DEBUG">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

December 6th, 2010

Posted In: logback, Maven

Leave a Comment

LinkedIn Auto Publish Powered By : XYZScripts.com