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

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

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

LinkedIn Auto Publish Powered By : XYZScripts.com