in Log4j, Maven

[Tutorial] Log4J with Maven profiles

Here is a quick tutorial to get your hands dirty with the Log4j logging framework.
Log4j allows logging requests to print to multiple output destinations, also known as appenders.
There are several output destinations: console, files, sockets, emails …
First create a Maven project :
mvn archetype:generate
Choose archetype number 109 (quickstart)


The structure of the generated project is the following :

You need to add 2 dependencies to the generated POM.xml file :

 <dependency>
	    <groupId>log4j</groupId>
	    <artifactId>log4j</artifactId>
	    <version>1.2.16</version>
  	</dependency>

	  <dependency>
				<groupId>com.oracle</groupId>
				<artifactId>ojdbc14</artifactId>
				<version>10.2.0.2.0</version>
		</dependency>

Create the /src/main/resources folder and add the following log4j.properties file :

# Author : Celinio Fernandes
# Note 1 : ALL < TRACE < DEBUG < INFO < WARN < ERROR < FATAL < OFF
# Note 2 : Use forward slash in paths : log4j.appender.FILE1.File=d:/temps/log4j1.log.

# Messages which levels are DEBUG and above will be displayed
#log4j.rootLogger=DEBUG, CONSOLE, FILE1, FILE2, FILE3, DB, FILE4
log4j.rootLogger=DEBUG, CONSOLE, FILE1, FILE2, FILE3, FILE4

#A variable
logPath = d:/temps/logs1

########################  CONSOLE output  ######################## 
 
log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender
log4j.appender.CONSOLE.Target=System.err
log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout
log4j.appender.CONSOLE.layout.conversionPattern=%d{yyyy-MM-dd HH:mm:ss,SSS} %c %-5p - %m%n
 
 
# Logging in separate files 
# http://logging.apache.org/log4j/1.2/apidocs/org/apache/log4j/RollingFileAppender.html
 
 
########################   1st file  ######################## 
 
# Create a first log file. Max size :1000KB. That means when the size of log4j1.log file will
# reach 1000KB, it will be renamed into log4j1.log.1 and a new file called log4j1.log will be created.
# log4j1.log.1 will not be written again. It becomes a backup.
# By using appender FILE1 the log file log4j1.log will be rolled over when it reaches 1000KB.
# When the roll-over occurs, the log4j1.log is automatically moved to log4j1.log.1.
# When log4j1.log again reaches 1KB, log4j1.log.1 is moved to log4j1.log.2 and log4j1.log is moved to log4j1.log.1.

log4j.appender.FILE1=org.apache.log4j.RollingFileAppender
log4j.appender.FILE1.File=${logPath}/log4j1.log
log4j.appender.FILE1.MaxFileSize=1000KB
#The maximum number of backup log files is set to 3, which means log4j1.log.3 is the last file created.
log4j.appender.FILE1.MaxBackupIndex=3
log4j.appender.FILE1.layout=org.apache.log4j.PatternLayout
# Append to the end of the file or overwrites the file at start.
log4j.appender.FILE1.Append=true
#What each line will print out
log4j.appender.FILE1.layout.conversionPattern=%d{yyyy-MM-dd HH:mm:ss,SSS} %c %-5p - %m%n
# this file will contain only messages which level are ERROR or above
log4j.appender.FILE1.Threshold=DEBUG

########################   2nd file : creates a new file based on file size  ########################

# Create a second log file. Max size :512K KB.
log4j.appender.FILE2=org.apache.log4j.RollingFileAppender
log4j.appender.FILE2.File=${logPath}/log4j2.log
log4j.appender.FILE2.MaxFileSize=512KB
log4j.appender.FILE2.MaxBackupIndex=3
# Append to the end of the file or overwrites the file at start.
log4j.appender.FILE2.Append=true
log4j.appender.FILE2.layout=org.apache.log4j.PatternLayout
log4j.appender.FILE2.layout.conversionPattern=%d{yyyy-MM-dd HH:mm:ss,SSS} %c %-5p - %m%n
# this file will contain only messages which level are FATAL
log4j.appender.FILE2.Threshold=FATAL

########################   3rd file : HTML layout ########################

# Define the file appender
log4j.appender.FILE3=org.apache.log4j.FileAppender
log4j.appender.FILE3.File=${logPath}/${nameHTMLFile}
# Append to the end of the file or overwrites the file at start.
log4j.appender.FILE3.Append=true

# Define the layout for file appender
log4j.appender.FILE3.layout=org.apache.log4j.HTMLLayout
log4j.appender.FILE3.layout.Title=HTML Layout Example
log4j.appender.FILE3.layout.LocationInfo=true


########################   4th file : creates a new file based on time  ########################

log4j.appender.FILE4=org.apache.log4j.DailyRollingFileAppender
log4j.appender.FILE4.File=${logPath}/log4jDaily.log
# Roll the log file at a certain time : 
# '.'yyyy-MM-dd-HH-mm : at the beginning of every minute
# '.'yyyy-MM-dd-HH : at the start of every hour
log4j.appender.FILE4.DatePattern='.'yyyy-MM-dd-HH
# Append to the end of the file or overwrites the file at start.
log4j.appender.FILE4.Append=true
log4j.appender.FILE4.layout=org.apache.log4j.PatternLayout
log4j.appender.FILE4.layout.ConversionPattern=[%5p] %d{mm:ss} (%F:%M:%L)%n%m%n%n


########################   Logging in database  ########################

# Define the DB appender
log4j.appender.DB=org.apache.log4j.jdbc.JDBCAppender

# Set JDBC URL
log4j.appender.DB.URL=jdbc:oracle:thin:@localhost:1521:XE

# Set Database Driver
log4j.appender.DB.driver=oracle.jdbc.driver.OracleDriver

# Set database user name and password
log4j.appender.DB.user=totoUser
log4j.appender.DB.password=totoPwd

# Define the layout for file appender
log4j.appender.DB.layout=org.apache.log4j.PatternLayout

# Set the SQL statement to be executed.
#log4j.appender.DB.sql=INSERT INTO LOGS VALUES('%x','%d','%C','%p','%m')
log4j.appender.DB.sql=INSERT INTO LOGS VALUES('%c',null,'%C','%p','%m')



################################  OTHER CONFIGURATION ########################"

# Print only messages of level WARN or above in the package samedi
log4j.logger.samedi=WARN


#Substitute symbol
# %c Logger, %c{2 } last 2 partial names
# %C Class name (full agony), %C{2 } last 2 partial names
# %d{dd MMM yyyy HH:MM:ss } Date, format see java.text.SimpleDateFormat, If no date format specifier is given then ISO8601 format is assumed.
# %F File name
# %l Location (caution: compiler-option-dependently)
# %L Line number
# %m user-defined message
# %M Method name
# %n Outputs the platform dependent line separator character or characters. 
# %p Level
# %r Milliseconds since program start
# %t Threadname
# %x, %X see Doku
# %% individual percentage sign
# Caution: %C, %F, %l, %L, %M slow down program run!

It is possible to set variables with Maven. For that to work, you need to add filtering to the resources :

  <build>
		<resources>
			<resource>
				<filtering>true</filtering>
				<directory>src/main/resources</directory>
			</resource>
		</resources>
	</build>

Complete the pom.xml file by adding 2 profiles : development and production. Here is the complete D:\temps\tutoLog4jProfiles\tutoL4JP\pom.xml file

<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
  xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 http://maven.apache.org/xsd/maven-4.0.0.xsd">
  <modelVersion>4.0.0</modelVersion>

  <groupId>com.tutoLog4JProfiles</groupId>
  <artifactId>tutoL4JP</artifactId>
  <version>1.0-SNAPSHOT</version>
  <packaging>jar</packaging>

  <name>tutoL4JP</name>
  <url>http://maven.apache.org</url>

  <properties>
    <project.build.sourceEncoding>UTF-8</project.build.sourceEncoding>
  </properties>

  <dependencies>
    <dependency>
      <groupId>junit</groupId>
      <artifactId>junit</artifactId>
      <version>3.8.1</version>
      <scope>test</scope>
    </dependency>
    
      <dependency>
	    <groupId>log4j</groupId>
	    <artifactId>log4j</artifactId>
	    <version>1.2.16</version>
  	</dependency>

	  <dependency>
				<groupId>com.oracle</groupId>
				<artifactId>ojdbc14</artifactId>
				<version>10.2.0.2.0</version>
		</dependency>
		
  </dependencies>
  
    <build>
		<resources>
			<resource>
				<filtering>true</filtering>
				<directory>src/main/resources</directory>
			</resource>
		</resources>
	</build>
  
  <profiles>
  	
		<profile>
			<id>development</id>
			<activation>
				<activeByDefault>true</activeByDefault> 
				<property>
          <name>environment.type</name>
          <value>dev</value>
        </property>
			</activation>
			<properties>
				 <nameHTMLFile>devHTML</nameHTMLFile>
			</properties>
		</profile>

		<profile>
			<id>production</id>
			<activation>
			 
			<property>
          <name>environment.type</name>
          <value>prod</value>
        </property>
			</activation>
			<properties>
				<nameHTMLFile>prodHTML</nameHTMLFile>
			</properties>
		</profile>

	</profiles>
	
			
</project>

Also add the app.properties file :

# application.properties
application.name=${nameHTMLFile}

When we compile the project, we can see that the property “application.name” defined in application.properties is set to devHTML, which maps to the property nameHTMLFile defined in the development profile, which is the default profile when none is declared.

Content of D:\temps\tutoLog4jProfiles\tutoL4JP\target\classes\app.properties :

# application.properties
application.name=devHTML

Here is out test class, D:\temps\tutoLog4jProfiles\tutoL4JP\src\main\java\com\tutoLog4JProfiles\App.java :

package com.tutoLog4JProfiles;

import org.apache.log4j.Logger;

public class App 
{
   private static final Logger  logger = Logger.getLogger(App.class);
	 
	    public static void main(String[] args) {
	    	
	    	 for(int i=1 ; i<10; i++) {
          System.out.println("Counter = " + i);
	        logger.debug("App message with DEBUG level");
	        logger.info("App message with INFO level ");
	        logger.warn("App message with WARN level ");
	        logger.error("App message with ERROR level ");
	        logger.fatal("App message with FATAL level ");
	      }
	    }
}

To test the program, I use the exec Maven plugin :

/cygdrive/d/temps/tutoLog4jProfiles/tutoL4JP
$ mvn exec:java -Dexec.mainClass=com.tutoLog4JProfiles.App
[INFO] Scanning for projects...
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] Building tutoL4JP 1.0-SNAPSHOT
[INFO] ------------------------------------------------------------------------
[INFO]
[INFO] >>> exec-maven-plugin:1.2:java (default-cli) @ tutoL4JP >>>
[INFO]
[INFO] <<< exec-maven-plugin:1.2:java (default-cli) @ tutoL4JP <<<
[INFO]
[INFO] --- exec-maven-plugin:1.2:java (default-cli) @ tutoL4JP ---
Counter = 1
2011-06-25 14:10:52,849 com.tutoLog4JProfiles.App DEBUG - App message with DEBUG level
2011-06-25 14:10:52,876 com.tutoLog4JProfiles.App INFO  - App message with INFO level
2011-06-25 14:10:52,877 com.tutoLog4JProfiles.App WARN  - App message with WARN level
2011-06-25 14:10:52,878 com.tutoLog4JProfiles.App ERROR - App message with ERROR level
2011-06-25 14:10:52,878 com.tutoLog4JProfiles.App FATAL - App message with FATAL level
Counter = 2
2011-06-25 14:10:52,879 com.tutoLog4JProfiles.App DEBUG - App message with DEBUG level
2011-06-25 14:10:52,880 com.tutoLog4JProfiles.App INFO  - App message with INFO level
2011-06-25 14:10:52,880 com.tutoLog4JProfiles.App WARN  - App message with WARN level
2011-06-25 14:10:52,881 com.tutoLog4JProfiles.App ERROR - App message with ERROR level
2011-06-25 14:10:52,881 com.tutoLog4JProfiles.App FATAL - App message with FATAL level
Counter = 3
2011-06-25 14:10:52,882 com.tutoLog4JProfiles.App DEBUG - App message with DEBUG level
2011-06-25 14:10:52,882 com.tutoLog4JProfiles.App INFO  - App message with INFO level
2011-06-25 14:10:52,883 com.tutoLog4JProfiles.App WARN  - App message with WARN level
2011-06-25 14:10:52,883 com.tutoLog4JProfiles.App ERROR - App message with ERROR level
2011-06-25 14:10:52,884 com.tutoLog4JProfiles.App FATAL - App message with FATAL level
Counter = 4
2011-06-25 14:10:52,885 com.tutoLog4JProfiles.App DEBUG - App message with DEBUG level
2011-06-25 14:10:52,886 com.tutoLog4JProfiles.App INFO  - App message with INFO level
2011-06-25 14:10:52,887 com.tutoLog4JProfiles.App WARN  - App message with WARN level
2011-06-25 14:10:52,887 com.tutoLog4JProfiles.App ERROR - App message with ERROR level
2011-06-25 14:10:52,887 com.tutoLog4JProfiles.App FATAL - App message with FATAL level
Counter = 5
2011-06-25 14:10:52,888 com.tutoLog4JProfiles.App DEBUG - App message with DEBUG level
2011-06-25 14:10:52,889 com.tutoLog4JProfiles.App INFO  - App message with INFO level
2011-06-25 14:10:52,889 com.tutoLog4JProfiles.App WARN  - App message with WARN level
2011-06-25 14:10:52,890 com.tutoLog4JProfiles.App ERROR - App message with ERROR level
2011-06-25 14:10:52,890 com.tutoLog4JProfiles.App FATAL - App message with FATAL level
Counter = 6
2011-06-25 14:10:52,891 com.tutoLog4JProfiles.App DEBUG - App message with DEBUG level
2011-06-25 14:10:52,909 com.tutoLog4JProfiles.App INFO  - App message with INFO level
2011-06-25 14:10:52,910 com.tutoLog4JProfiles.App WARN  - App message with WARN level
2011-06-25 14:10:52,910 com.tutoLog4JProfiles.App ERROR - App message with ERROR level
2011-06-25 14:10:52,911 com.tutoLog4JProfiles.App FATAL - App message with FATAL level
Counter = 7
2011-06-25 14:10:52,913 com.tutoLog4JProfiles.App DEBUG - App message with DEBUG level
2011-06-25 14:10:52,913 com.tutoLog4JProfiles.App INFO  - App message with INFO level
2011-06-25 14:10:52,914 com.tutoLog4JProfiles.App WARN  - App message with WARN level
2011-06-25 14:10:52,914 com.tutoLog4JProfiles.App ERROR - App message with ERROR level
2011-06-25 14:10:52,914 com.tutoLog4JProfiles.App FATAL - App message with FATAL level
Counter = 8
2011-06-25 14:10:52,924 com.tutoLog4JProfiles.App DEBUG - App message with DEBUG level
2011-06-25 14:10:52,924 com.tutoLog4JProfiles.App INFO  - App message with INFO level
2011-06-25 14:10:52,925 com.tutoLog4JProfiles.App WARN  - App message with WARN level
2011-06-25 14:10:52,926 com.tutoLog4JProfiles.App ERROR - App message with ERROR level
2011-06-25 14:10:52,926 com.tutoLog4JProfiles.App FATAL - App message with FATAL level
Counter = 9
2011-06-25 14:10:52,928 com.tutoLog4JProfiles.App DEBUG - App message with DEBUG level
2011-06-25 14:10:52,928 com.tutoLog4JProfiles.App INFO  - App message with INFO level
2011-06-25 14:10:52,928 com.tutoLog4JProfiles.App WARN  - App message with WARN level
2011-06-25 14:10:52,929 com.tutoLog4JProfiles.App ERROR - App message with ERROR level
2011-06-25 14:10:52,929 com.tutoLog4JProfiles.App FATAL - App message with FATAL level
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 1.681s
[INFO] Finished at: Sat Jun 25 14:10:52 CEST 2011
[INFO] Final Memory: 4M/15M
[INFO] ------------------------------------------------------------------------

4 log files are generated in D:\temps\logs1 :

If we run the test again, then log4jDaily.log is renamed to log4jDaily.log.2011-06-25-13. The file is rolled at the start of every hour :

Now let’s compile the project again with the Production profile using the following command :

mvn compile -P Production


The new content of app.properties is:

# application.properties
application.name=prodHTML

And the content of log4j.properties contains the following lines :

# Define the file appender
log4j.appender.FILE3=org.apache.log4j.FileAppender
log4j.appender.FILE3.File=${logPath}/prodHTML

So from now on, the generated HTML file will be called prodHTML:

Log4J can generate logs in HTML format, that’s what the org.apache.log4j.HTMLLayout is about :

The org.apache.log4j.jdbc.JDBCAppender is used to insert logs into the database:

The SQL script for the table :

CREATE TABLE LOGS
   (USER_ID VARCHAR(50) NOT NULL,
    DATED   DATE,
    LOGGER  VARCHAR(50) NOT NULL,
    LEVELMESSAGE   VARCHAR(10) NOT NULL,
    MESSAGE VARCHAR(1000) NOT NULL
   );
 

One thing to understand and keep in mind: the rootLogger level determines the minimum log level that will be taken into account in all log files.
That means that if you set the rootLogger level to DEBUG then all levels of traces from DEBUG to OFF levels will be displayed.
If you set the rootLogger level to INFO and the threshold of FILE1 to DEBUG then DEBUG traces will not be displayed since the minimum level was set to INFO.
Remember :
ALL < TRACE < DEBUG < INFO < WARN < ERROR < FATAL < OFF