Showing posts with label Logback. Show all posts
Showing posts with label Logback. Show all posts

JUnit, Logback, Maven with Spring 3

In this series we have already learnt to set up a basic Spring MVC application and learnt how to handle forms in Spring MVC. Now it is time to take on some more involved topics. However, before we venture into deeper waters, let's get some basics set up.

Unit testing
I am no TDD evangelist. There I said it. I have never ever been able to write any software where for every piece of code, I have written a test first and then code. If you have done so and are gainfully employed by coding, please do let me know. I would seriously like to know you better. Seriously.

My difference in opinion with TDD ends there. Apart from writing test before code - which somehow I simply can't get my brain to work with - I am a huge supporter of unit testing. I am a firm believer of using JUnit to test all functionality (public but non getter setter, methods). I am a huge fan of using cobertura to report on code coverage. I am a huge fan of maven which allows me to bring this all together in a nice HTML report with just one command.

I will use JUnit 4 for this series. Let's add the dependencies.

File: \pom.xml

<properties>                                                     
    <junit.version>4.10</junit.version>
</properties>  

<!-- Unit testing framework. -->       
<dependency>                           
    <groupId>junit</groupId>           
    <artifactId>junit</artifactId>     
    <version>${junit.version}</version>
    <scope>test</scope>                
</dependency>                          

And let's add a dumb class to demonstrate testing.

File: /src/main/java/org/academy/HelloWorld.java
package org.academy;

public class HelloWorld {
  private String message = "Hello world. Default setting."; 
  public String greet(){
    return message; 
  }
  
  public String getMessage() {
    return message;
  }
  public void setMessage(String message) {
    this.message = message;
  }
}
And finally the JUnit to test it.

File: src/test/java/org/academy/HelloWorldTest.java
package org.academy;

import static org.junit.Assert.*;

import org.junit.Test;
import org.junit.runner.RunWith;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.test.context.ContextConfiguration;
import org.springframework.test.context.junit4.SpringJUnit4ClassRunner;

@RunWith(SpringJUnit4ClassRunner.class)
@ContextConfiguration
public class HelloWorldTest {

  @Autowired
  HelloWorld helloWorld;
  
  private final static Logger logger = LoggerFactory
      .getLogger(HelloWorldTest.class);

  @Test
  public void test() {    
    logger.debug(helloWorld.greet());
    assertEquals(helloWorld.greet(), "Hello world, from Spring.");
  }
}
You would have noticed that the helloWorld within the unit test have never been initialized in the code. This is the bit of IoC magic of Spring. To make this work, we have used @RunWith, @ContextConfiguration and @Autowired. And I have also given Spring enough information to be able to create an instance of HelloWorld and then inject it to HelloWorldTest.helloWorld. Also, the assertEquals is checking for a very different message than what is actually hard coded in the HelloWorld class. This was done in a xml file mentioned below. Please do note the location of the file within Maven structure.

File: /src/test/resources/org/academy/HelloWorldTest-context.xml
<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
  xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xmlns:p="http://www.springframework.org/schema/p"
  xmlns:context="http://www.springframework.org/schema/context"
  xsi:schemaLocation="http://www.springframework.org/schema/beans 
http://www.springframework.org/schema/beans/spring-beans-3.0.xsd 
http://www.springframework.org/schema/context 
http://www.springframework.org/schema/context/spring-context-3.0.xsd">

  <bean id="helloWorld" class="org.academy.HelloWorld">
    <property name="message" value="Hello world, from Spring." />
  </bean>
</beans>
There are multiple ways I could have provided this configuration file to the unit test. @RunWith(SpringJUnit4ClassRunner.class) is a nice thing to add but is not mandatory. What I have provided here is just the vanilla approach that works in most cases, but I encourage the audience to experiment.

Unit test coverage / code coverage.
I don't feel there is enough said about the importance of automated / semi automated / easy way of reporting on code coverage - both for individual developers and technical heads. Unless you are practising TDD religiously (which by the way I have mentioned before I personally have never been able to), it is absolutely impossible for even an individual developer to know if all logic branches of a code are covered by unit test. I am not even going to talk about how a technical head of a team / organization is going to ensure that his product(s) are sufficiently unit tested. I personally believe, any software product which is not sufficiently unit tested and test coverage reported, is an unacceptable risk. Period. Admittedly a bit of a hard stance, but that's how it is.

A bit of my conviction for the hard stance comes from the fact that it is so darn easy to report on test coverage. I will use cobertura in this example. You need to add cobertua to Maven pom.

File: pom.xml
<!-- Reporting -->                                              
<plugin>                                                              
  <groupId>org.apache.maven.plugins</groupId>                       
  <artifactId>maven-site-plugin</artifactId>                        
  <version>3.0</version>                                            
  <configuration>                                                   
    <reportPlugins>                                               
      <!-- Reporting on success / failure of unit tests -->     
      <plugin>                                                  
        <groupId>org.apache.maven.plugins</groupId>           
        <artifactId>maven-surefire-report-plugin</artifactId> 
        <version>2.6</version>                                
      </plugin>                                                 
      <!-- Reporting on code coverage by unit tests. -->        
      <plugin>                                                  
        <groupId>org.codehaus.mojo</groupId>                  
        <artifactId>cobertura-maven-plugin</artifactId>       
        <version>2.5.1</version>                              
        <configuration>                                       
          <formats>                                         
            <format>xml</format>                          
            <format>html</format>                         
          </formats>                                        
        </configuration>                                      
      </plugin>                                                 
    </reportPlugins>                                              
  </configuration>                                                  
And once you have done this, and added JUnit, and added an actual JUnit test, you just need to run
mvn -e clean install site
to create a nice looking HTML based code coverage report. This report will allow you to click through source code under test and give you nice green coloured patches for unit tested code and red coloured patches for those that slipped through the cracks.

Logging
Log4j is good, Logback is better. Just don't use System.out.println() for logging.

You could go a long way without proper logging. However, I have spent far too many weekends and nights chasing down production issues, with business breathing down my neck, wishing there was some way to know what was happening in the app rather than having to guess all my way. Now a days, with mature api like slf4j and stable implementation like logback, a developer needs to add just one extra line per class to take advantage of enterprise grade logging infrastructure. It just does not make sense not to use proper logging right from the beginning of any project.

Add slf4j and logback to Maven dependencies.

File: \pom.xml.
[...]
<logback.version>1.0.6</logback.version>          
<jcloverslf4j.version>1.6.6</jcloverslf4j.version>
[...]
<!-- Logging -->                            
<dependency>                                
  <groupId>ch.qos.logback</groupId>       
  <artifactId>logback-classic</artifactId>
  <version>${logback.version}</version>   
</dependency>   
[...]
<dependency>                                  
  <groupId>org.slf4j</groupId>              
  <artifactId>jcl-over-slf4j</artifactId>   
  <version>${jcloverslf4j.version}</version>
</dependency>                                 
[...]                            
Ensure that Spring's default logging i.e. commons logging is excluded. If you are wondering if logback is really this good that I claim it to be why did Spring not opt for it to start with. In my defense, here is a link at Spring's official blog where they say "If we could turn back the clock and start Spring now as a new project it would use a different logging dependency. Probably the first choice would be the Simple Logging Facade for Java (SLF4J),..."

File: \pom.xml.
   
<dependency>                                         
  <groupId>org.springframework</groupId>           
  <artifactId>spring-context</artifactId>          
  <version>${org.springframework.version}</version>
  <exclusions>                                     
    <exclusion>                                  
      <groupId>commons-logging</groupId>       
      <artifactId>commons-logging</artifactId> 
    </exclusion>                                 
  </exclusions>                                    
</dependency>                                        

[...]                                                  

<dependency>                                         
  <groupId>org.springframework</groupId>           
  <artifactId>spring-test</artifactId>             
  <version>${org.springframework.version}</version>
  <scope>test</scope>                              
  <exclusions>                                     
    <exclusion>                                  
      <groupId>commons-logging</groupId>       
      <artifactId>commons-logging</artifactId> 
    </exclusion>                                 
  </exclusions>                                    
</dependency>                                        
Provide configuration for logback.

File: /src/main/resources/logback.xml
                                                    
<?xml version="1.0" encoding="UTF-8"?>
<configuration>
  <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
      <pattern>%d %5p | %t | %-55logger{55} | %m %n</pattern>
    </encoder>
  </appender>

  <logger name="org.springframework">
    <level value="INFO" />
  </logger>

  <root>
    <level value="DEBUG" />
    <appender-ref ref="CONSOLE" />
  </root>
</configuration>
                                     
Finally, add the magic one liner at the beginning of each class that needs logging (that ought to be all classes).

File: src/test/java/org/academy/HelloWorldTest.java
[...]                                                    
private final static Logger logger = LoggerFactory  
  .getLogger(HelloWorldTest.class);           
[...]
logger.debug(helloWorld.greet());
[...]
There you are all set up. In the next section we will start working with the data that we collected from user using forms. We will start by validating form data.

Till then, happy coding.

Want to read more?

Here are the links to earlier articles in this series.
Hello World with Spring 3 MVC
Handling Forms with Spring 3 MVC

And, of course these are highly recommended
Spring 3 Testing with JUnit 4.
Running unit tests with the Spring Framework
@RunWith JUnit4 with BOTH SpringJUnit4ClassRunner and Parameterized
Issue with Junit and Spring.
If you want to get in touch, you can look me up at Linkedin or Google + .

Logging revisited.

Hi, I am back again with my rant about logging as an inherent part of any application design and development. I am a big fan of strong basics, and in my humble opinion logging is one of those often overlooked but basic critical element of any enterprise grade application. I have written about this before here. This article was also reproduced at javalobby at this link. They are not really mandatory read to make sense of the current article, but it might help to give them a cursory look, to set context for this article.

In the first article, I introduced logging as a high benefit, low cost alternative to the omnipresent System.out.println(), that all java folks love so much. I had used log4j in that article. Log4j is a solid framework and delivers on it's promise. In all the years that I have used it, it has never let me down. I can whole heartedly recommend it. However, having said that, there are few alternatives also, which have been around in the market for a while and I am happy to say that at least one of them seem to be challenging log4j in it's own turf. I am talking about Logback.

It is certainly not new kid in the block - and that is one of the reasons I am suggesting you consider this for enterprise grade applications to start with. A quick look at Maven Central suggests that the first version was published way back in 2006. Between 2006 and 8-June2012 - which is when the latest version was pushed to Maven Central, there have been 46 versions. Compare this with log4j. The first version was pushed in Maven Central in 2005 and the last on 26 May 2012, and between these there have been a total of 14 different versions. I do not mean to use this data to compare these two frameworks. The only intent is to assure the reader that Logback have been around long enough and is current enough to be taken seriously.

Being around is one thing and making your mark is different. As far as ambition and intent goes, Logback makes it pretty clear that it intends to be successor of log4j - and says that in clear words at it's homepage. Of courser there is an exhaustive list of features / benefits that Logback claims over Log4j. You can read about them at this link. That's it really. The point of this article is that I am suggesting that while designing and developing a enterprise grade java based applications, look at logging a bit more carefully and also consider using Logback.

A few of the audience at this point, I am hoping, will like to roll up their sleeves, fire up their favorite editor and take Logback out for a spin. If you are one of them, then you and I have something in common. You might want to read on.

The very first thing that Logback promises is faster implementation (at this link). Really? I would like to check that claim.

I start by creating a vanilla java application using Maven. 

File: MavenCommands.bat
call mvn archetype:create ^
 -DarchetypeGroupId=org.apache.maven.archetypes ^
 -DgroupId=org.academy ^
 -DartifactId=logger
This unfortunately is preloaded with JUnit 3. I set up JUnit 4 and also add Contiperf, so that I could run the tests multiple times - something that would come in handy if I were to check performance.

File: /logger/pom.xml
[...]

                                                          
 UTF-8
        4.10         
        2.2.0
 [...]                           
                                                   

[...]
                         
                    
                           
 junit           
 junit     
 ${junit.version}
 test                
                                                         
     
                                
 org.databene         
 contiperf      
 ${contiperf.version} 
 test                     

Also, I like to explicitly control the java version that is being used to compile and execute my code.

File: /logger/pom.xml
[...]

2.0.2
1.7                                    

[...]

 
                                                        
 org.apache.maven.plugins                 
 maven-compiler-plugin              
 ${maven-compiler-plugin.version}         
                                              
  ${java.version}                        
  ${java.version}                        
                                             
 

Last of configurations - for the time being. Slap on surefire to run unit tests.

File: /logger/pom.xml
[...]

2.12                                

[...]

                         
                                                        
 org.apache.maven.plugins                 
 maven-surefire-plugin              
 ${maven-surefire-plugin.version}         
                                               
                                              
   org.apache.maven.surefire        
   surefire-junit47           
   ${maven-surefire-plugin.version} 
                                             
                                              
                                              
  -XX:-UseSplitVerifier
                                             
        

Please note, I have taken the pains of adding all these dependencies to this article with their versions, just to ensure that should you try this yourself, you know exactly what was the software configuration of my test. 

Now, let us finally add the unit tests.

File: /logger/src/test/java/org/academy/AppTest.java
public class AppTest {                                 
 private final static Logger logger = LoggerFactory 
   .getLogger(AppTest.class);                 
                                                       
 @Rule                                              
 public ContiPerfRule i = new ContiPerfRule();      
                                                       
 @Test                                              
 @PerfTest(invocations = 10, threads = 1)           
 @Required(max = 1200, average = 1000)              
 public void test() {                         
  for(int i = 0; i<10000 ; i++){          
   logger.debug("Hello {}", "world.");        
  }                                              
 }                                                  
}  

So, we have used the logger in my unit test but have not added an implementation of logger. What I intend to do is to add log4j (with slf4j) and logback (with inherent support of slf4j) one by one and run this simple test multiple times to compare performance.

To add log4j I used this setting.

File: /logger/pom.xml
                                
 org.slf4j            
 slf4j-api      
 ${slf4j.version}     
                               
                                
 org.slf4j            
 jcl-over-slf4j 
 ${slf4j.version}     
 runtime                  
                               
                                
 org.slf4j            
 slf4j-log4j12  
 ${slf4j.version}     
 runtime                  
 
and for logback I used this setting.

File: /logger/pom.xml
                                
 ch.qos.logback       
 logback-classic
 ${logback.version}   
   
with the following versions.

File: /logger/pom.xml
1.6.1    
1.0.6

For either of these logger framework to actually log anything you will have to add a file telling loggers what to log and where.

File: src/main/resources/log4j.properties
# Set root logger level to DEBUG and its only appender to A1.
log4j.rootLogger=DEBUG, A1

# configure A1 to spit out data in console
log4j.appender.A1=org.apache.log4j.ConsoleAppender
log4j.appender.A1.layout=org.apache.log4j.PatternLayout 
log4j.appender.A1.layout.ConversionPattern=%d [%t] %-5p %c - %m%n
Finally, for the moment of truth. I ran the tests thrice with each framework i.e. logback and log4j. Essentially I log.debug() a string 1000,000 times in each test and timed them. And this is how the final figures came out.

Framework 1st run 2nd run 3rd run
Logback 0.375 seconds 0.375 seconds 0.406 seconds
Log4j 0.454 seconds 0.453 seconds 0.454 seconds


As far as this little experiment goes, Logback clearly performs faster than Log4j. Of course this is overly simplistic experiment and many valid scenarios have not been considered. For example, we have not really used vanilla log4j. We have used log4j in conjunction with the slf4j API, which is not quite the same thing. Also, being faster is not the only consideration. Log4j works asynchronously (read here and here) whereas as far as I know Logback does not. Logback has quite a few nifty features that Log4j does not.

So, in isolation this little code does not really prove anything. If at all, it brings me back to the first point that I made - Logback is a serious potential and worth a good look if you are designing / coding an enterprise grade java based application.

That is all for this article. Happy coding.

Want to read on? May I suggest ...


If you want to get in touch, you can look me up at Linkedin or Google + .

Log don't SOP

Stick to basics. This is generally my opening line to any discussion around best architecture and coding practices.

People - particularly those who are newcomers (say who have spent less than 5 years in the IT industry) - tend to feel a bit cheated with this statement. Generally the expectation is that we will discuss what I term as *ity ( flexibility, modularity, scalability, ...). I generally tend to swipe all those glamorous words aside and talk about just the basics. I leave the *ity discussions to salesperson of frameworks and products.

Ranting aside, I wanted to talk about one of the basic practices that I think is grossly underutilized. Logging and auditing. Particularly I wanted to talk about logging in this article. Auditing, in my mind, is limited by the quality of logging that we have (of course that is not strictly true in all scenarios, but you get the general idea, I hope).

As far as logging is concerned, I maintain that all professional code, need to have a well thought out logging strategy. Period. I have heard all sort of excuses and logic against it - too small code, not really strategic, don't have time etc etc - and my personal stand is, I don't buy any one of those excuses against logging. If you need to put in a single "System.out.println" in your code, don't. Put a logger.debug instead.

Logging framework / tool is free. It is simple. It could do what System.out.println would have done. It could do much much more. You should have put a logger anyway. Just take a deep breath, break the habit of System.out.println, follow the simple steps that I have mentioned here, do yourself and your project a good karma.

What do I need to do to use logger instead of using System.out.println()?


Use log4j. You could use logback. It's your choice. I am just giving a vanilla version that works.

You could just get the jars and put them in your classpath. If you are using Maven (and in my humble opinion you should) you could just tell pom to use log4j with slf4j. It will give you the flexibility to move to logback on a later day if you so wanted. Add these dependencies.
<!-- Logging -->
<dependency>
 <groupId>org.slf4j</groupId>
 <artifactId>slf4j-api</artifactId>
 <version>${slf4j.version}</version>
</dependency>
<dependency>
 <groupId>org.slf4j</groupId>
 <artifactId>jcl-over-slf4j</artifactId>
 <version>${slf4j.version}</version>
 <scope>runtime</scope>
</dependency>
<dependency>
 <groupId>org.slf4j</groupId>
 <artifactId>slf4j-log4j12</artifactId>
 <version>${slf4j.version}</version>
 <scope>runtime</scope>
</dependency>
Mention the correct version. I am using 1.6.1 in the example below. I guess the latest is 1.6.4 at the time of writing this article. Feel free to check that out. 

<properties>
...
<slf4j.version>1.6.1</slf4j.version>
... 
</properties>


Configure log4j to write to console like the System.out.println would have done. In my case the configuration file is at /src/main/resources/log4j.properties. I use Maven. If you dont use Maven, the basic fundamental is that this configuration should be available at the classpath. 

# Set root logger level to DEBUG and its only appender to A1.
log4j.rootLogger=DEBUG, A1

# configure A1 to spit out data in console
log4j.appender.A1=org.apache.log4j.ConsoleAppender
log4j.appender.A1.layout=org.apache.log4j.PatternLayout 
log4j.appender.A1.layout.ConversionPattern=%d [%t] %-5p %c - %m%n


That's if you are done with all the configurations. Now in each of your classes, before you do anything else, put in the following line. 

private final static Logger logger = LoggerFactory.getLogger(YourClass.class);

And wherever you need to write a System.out.println(message) write the following 
logger.debug(message); 
So, instead of just writing System.out.println (and being lazy) you logged the message (and did the right thing). It took you all of 10 minutes (ok, lets be really generous with time and account for the coffee breaks, it took you half a day) to get the logging framework in place.

It means you will never have to go back and cleanse your code of System.out.println(). It means you will never have to go and face the customer / client and explain the funny messages showing up on console. It means you will always have a nice way of switching on debugging in production when you need. You will be able to switch on debugging and switch off really easily. I can go on and on about the benefits.  But I hope the point has been proved that the 10 minutes (or half a day as the case might be) is definitely worth it.

So, that's one more discussion about "sticking to basics". Happy coding.
If you want to get in touch, you can look me up at Linkedin or Google + .