Logging met Spring AOP (SLF4J/log4j)

August 13th, 2012 | 11 min read | AOP, Maven, SLF4J, Spring, Web

In deze tutorial ga je een combinatie van logging en Aspect Oriented Programming of AOP zien. Logging is een heel belangrijk concept in software, het stelt ons niet enkel in staat om de flow bij te houden tijdens het debuggen, maar in latere fases van de ontwikkeling van de software kan het ook de nodige logging doen die handig is voor de klant.

Echter heeft logging ook zo z’n problemen. Logging moet eigenlijk op verschillende plaatsen in de code terecht komen, dit wilt zeggen dat je eigenlijk een enorme koppeling gaat hebben tussen je logging framework enerzijds en je eigen code anderzijds.

Dit is waar AOP van pas komt. AOP zorgt ervoor dat bepaalde blokken code uitgevoerd worden op bepaalde punten in de flow van je programma, zonder dat je die code daar overal moet gaan plaatsen.

Heads up!

In deze tutorial wordt met regelmaat verwezen naar mijn vorige Java tutorials. Het is dus handig dat je deze (zeker de eerste) eens doorneemt.

Project opzetten

De eerste stap zoals in elk voorbeeld is dat we een project gaan aanmaken en al enkele packages/configuratie-files gaan aanmaken. Omdat we dit ondertussen toch al meerdere keren gedaan hebben ga ik niet alles stap voor stap herhalen, de bedoeling is gewoonweg dat de structuur van je project eruit moet zien als hieronder.

De file

log4j.xml

is nieuw in deze tutorial, dit is gewoonweg een XML file (geen Spring bean configuration file dus).

Maven configuratie

In pom.xml zullen we weer een aantal dependencies moeten toevoegen, namelijk van het Spring framework en de logging frameworks die ik ga gebruiken.  Deze dependencies zijn:

<!-- Spring framework -->
<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-core</artifactId>
    <version>${spring.version}</version>
    <exclusions>
        <exclusion>
            <groupId>commons-logging</groupId>
            <artifactId>commons-logging</artifactId>
        </exclusion>
    </exclusions>
</dependency>
<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-web</artifactId>
    <version>${spring.version}</version>
</dependency>
<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-context</artifactId>
    <version>${spring.version}</version>
    <exclusions>
        <exclusion>
            <groupId>commons-logging</groupId>
            <artifactId>commons-logging</artifactId>
        </exclusion>
    </exclusions>
</dependency>
<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-context-support</artifactId>
    <version>${spring.version}</version>
</dependency>
<dependency>
    <groupId>org.springframework</groupId>
    <artifactId>spring-webmvc</artifactId>
    <version>${spring.version}</version>
</dependency>

<!-- Apache Commons -->
<dependency>
    <groupId>org.apache.commons</groupId>
    <artifactId>commons-lang3</artifactId>
    <version>${commons.version}</version>
</dependency>

<!-- Web -->
<dependency>
    <groupId>javax.servlet</groupId>
    <artifactId>jstl</artifactId>
    <version>${jstl.version}</version>
    <type>jar</type>
    <scope>compile</scope>
</dependency>

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

<dependency>
    <groupId>log4j</groupId>
    <artifactId>log4j</artifactId>
    <version>${log4j.version}</version>
    <exclusions>
        <exclusion>
            <groupId>javax.mail</groupId>
            <artifactId>mail</artifactId>
        </exclusion>
        <exclusion>
            <groupId>javax.jms</groupId>
            <artifactId>jms</artifactId>
        </exclusion>
        <exclusion>
            <groupId>com.sun.jdmk</groupId>
            <artifactId>jmxtools</artifactId>
        </exclusion>
        <exclusion>
            <groupId>com.sun.jmx</groupId>
            <artifactId>jmxri</artifactId>
        </exclusion>
    </exclusions>
</dependency>

<!-- AspectJ -->
<dependency>
    <groupId>org.aspectj</groupId>
    <artifactId>aspectjrt</artifactId>
    <version>${aspectj.version}</version>
</dependency>
<dependency>
    <groupId>org.aspectj</groupId>
    <artifactId>aspectjlib</artifactId>
    <version>1.6.2</version>
</dependency>
<dependency>
    <groupId>org.aspectj</groupId>
    <artifactId>aspectjweaver</artifactId>
    <version>${aspectj.version}</version>
</dependency>

<!-- AOP dependency -->
<dependency>
    <groupId>cglib</groupId>
    <artifactId>cglib</artifactId>
    <version>2.2</version>
</dependency>

De bijhorende properties (voor de versienummers) zijn:

<!-- Versions -->
<spring.version>3.1.2.RELEASE</spring.version>
<commons.version>3.1</commons.version>
<slf4j.version>1.6.4</slf4j.version>
<log4j.version>1.2.15</log4j.version>
<jstl.version>1.2</jstl.version>
<aspectj.version>1.6.12</aspectj.version>

Web descriptor

De web descriptor is dezelfde als we ondertussen al een paar keer hebben gebruikt. De code hiervan kan je hieronder vinden.

<?xml version="1.0"?>
<web-app xmlns="http://java.sun.com/xml/ns/javaee" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
    xsi:schemaLocation="http://java.sun.com/xml/ns/javaee http://java.sun.com/xml/ns/javaee/web-app_3_0.xsd"
    version="3.0">
    <servlet>
        <servlet-name>springmvc</servlet-name>
        <servlet-class>org.springframework.web.servlet.DispatcherServlet</servlet-class>
        <init-param>
            <param-name>contextConfigLocation</param-name>
            <param-value>classpath:springmvc-servlet.xml</param-value>
        </init-param>
    </servlet>

    <servlet-mapping>
        <servlet-name>springmvc</servlet-name>
        <url-pattern>*.html</url-pattern>
    </servlet-mapping>

    <listener>
        <listener-class>org.springframework.web.context.ContextLoaderListener</listener-class>
    </listener>
</web-app>

Domain class

Net zoals vorige keren gaan we weer gebruik maken van de User domain class. De code hiervan  kan je hieronder vinden.

package be.g00glen00b.domain;

import java.util.Calendar;

import org.apache.commons.lang3.StringUtils;

public class User {

    private String name;
    private String firstName;
    private Calendar birthDay;
    private boolean isMale;

    public User(String name, String firstName, Calendar birthDay, boolean isMale) {
        setName(name);
        setFirstName(firstName);
        setBirthDay(birthDay);
        setMale(isMale);
    }

    public User() { }

    public String getName() {
        return name;
    }

    public void setName(String name) {
        this.name = name;
    }

    public String getFirstName() {
        return firstName;
    }

    public void setFirstName(String firstName) {
        this.firstName = firstName;
    }

    public Calendar getBirthDay() {
        return birthDay;
    }

    public void setBirthDay(Calendar birthDay) {
        this.birthDay = birthDay;
    }

    public boolean isMale() {
        return isMale;
    }

    public void setMale(boolean isMale) {
        this.isMale = isMale;
    }

    @Override
    public String toString() {
        return StringUtils.join(getFirstName(), " ", getName());
    }
}

Service

Wat nieuw is in dit verhaal is dat we een service gaan maken die User objecten gaat aanmaken. Volgens het MVC pattern is het de bedoeling om zoveel mogelijk business logica uit de controllers te halen en in een service/het model onder te brengen.

Onze service stelt echter niet veel voor:

package be.g00glen00b.service;

import java.util.GregorianCalendar;

import org.springframework.stereotype.Component;

import be.g00glen00b.domain.User;

@Component
public class UserService {

    public User getBillGates() {
        return new User("Gates", "Bill", new GregorianCalendar(1955, 9, 28), true);
    }

    public User getSteveJobs() {
        return new User("Jobs", "Steve", new GregorianCalendar(1955, 2, 24), true);
    }
}

Zoals je ook kan zien maken we hier gebruik van de annotation

@Component

. Deze annotation zorgt ervoor dat deze class beheerd zal worden door de Spring container.

De controller

De controller zal er dus ook iets anders uit zien dan gewoonlijk. De eerste verandering is dat we nu twee pagina’s gaan hebben in plaats van één. De andere verandering is dat we nu gebruik gaan maken van de service die we hierboven gedefinieerd hebben.

package be.g00glen00b.controller;

import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Controller;
import org.springframework.ui.ModelMap;
import org.springframework.web.bind.annotation.RequestMapping;

import be.g00glen00b.service.UserService;

@Controller
public class MainController {

    @Autowired
    private UserService service;

    @RequestMapping(value = "/bill.html")
    public String getBill(ModelMap model) {
        model.addAttribute("user", service.getBillGates());
        return "index";
    }

    @RequestMapping(value = "/steve.html")
    public String getSteve(ModelMap model) {
        model.addAttribute("user", service.getSteveJobs());
        return "index";
    }
}

Een aspect

Nu komt eigenlijk het leukste van deze hele tutorial, namelijk het AOP gedeelte. AOP is een techniek die je in staat stelt code (aspects) op verschillende plaatsen in de code (pointcuts) tussen te weven (at compile time).

Ik ga een aspect schrijven die logt wanneer een methode in de

UserService

wordt opgeroepen. De code hiervan vind je hieronder.

package be.g00glen00b.aop;

import org.apache.commons.lang3.StringUtils;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.Aspect;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

@Aspect
public class LoggingAspect {

    public Object logService(final ProceedingJoinPoint joinPoint) throws Throwable {
        Logger logger = LoggerFactory.getLogger(joinPoint.getTarget().getClass());
        logger.info(StringUtils.join(joinPoint.getSignature().getName(), "() called"));
        long currentTicks = System.currentTimeMillis();
        try {
            Object result = joinPoint.proceed();
            logger.info(StringUtils.join(joinPoint.getSignature().getName(), "() executed in ", Long.toString(System.currentTimeMillis() - currentTicks), "ms"));
            return result;
        } catch (Throwable ex) {
            logger.info(StringUtils.join(joinPoint.getSignature().getName(), "() failed"));
            throw ex;
        }
    }
}

Op het eerste zicht ziet deze methode er enorm ingewikkeld uit, maar dit valt echter nog goed mee.

Ik maak in dit project gebruik van log4j met SLF4J als een facade. SLF4J zal ons in staat stellen om onafhankelijk van het logging framework dat erachter zit, dingen weg te kunnen schrijven naar de logs.  De

Logger

interface is diegene die we eigenlijk gebruiken om weg te schrijven naar de logs.

Verder wordt er bepaald hoeveel miliseconden de methode  erover gedaan heeft om tot z’n resultaat te komen, dit wordt dan gelogd.

Mocht er een exception optreden tijdens het uitvoeren van de methode, dan wordt er ook gelogd dat er een fout is opgetreden.

De class

StringUtils

maakt deel uit van de Apache Commons library en zorgt ervoor dat we strings kunnen aan elkaar plakken. Java stelt ons al in staat dit te doen (met de

+

operator), maar als we naar de performantie kijken, dan laat dit te wensen over (dit heeft te maken met het feit dat een String immutable is).

Spring configuration

Dit keer zullen we eindelijk eens wat meer de configuratiemogelijkheden van Spring gaan gebruiken. Eerst gaan we echter beginnen met de MVC gerelateerde zaken.

springmvc-servlet.xml

De code hier is niet veel verschillend ten opzichte van voorgaande tutorials. Het enige verschil is dat we de package

be.g00glen00b.service

hebben toegevoegd als een door Spring beheerde package.

Dit doen we omdat we

UserService

door Spring willen laten beheren.

<?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:context="http://www.springframework.org/schema/context"
    xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans.xsd
        http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context.xsd"
    default-autowire="byName">

    <bean id="viewResolver"
        class="org.springframework.web.servlet.view.InternalResourceViewResolver">
        <property name="prefix" value="/WEB-INF/views/" />
        <property name="suffix" value=".jsp" />
    </bean>

    <context:component-scan base-package="be.g00glen00b.controller" />
    <context:component-scan base-package="be.g00glen00b.service" />
    <context:annotation-config />

    <import resource="classpath:spring-aop.xml" />
</beans>

spring-aop.xml

We hebben daarnet al een advice geschreven (de nodige code die uitgevoerd moet worden). Dit advice moet weliswaar nog gekoppeld worden aan de code in de service. Zoals eerder gezegd doen we dit met pointcuts, deze pointcuts kunnen we configureren via Spring beans.

<?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:aop="http://www.springframework.org/schema/aop"
    xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans.xsd
        http://www.springframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop-3.1.xsd">
    <bean name="loggingAspect" class="be.g00glen00b.aop.LoggingAspect" />
    <aop:config>
        <!-- The Pointcut(s). -->
        <aop:pointcut id="loggingPointcut"
            expression="within(be.g00glen00b.service..*) and execution(public * *(..))" />

        <!-- The Advice(s). -->
        <aop:aspect id="loggingAspect" ref="loggingAspect">
            <aop:around pointcut-ref="loggingPointcut" method="logService" />
        </aop:aspect>
    </aop:config>
</beans>

Zoals je kan zien hebben we hier een referentie naar de class waar de advice in staat (

LoggingAspect

). Daarnaast hebben we ook een pointcut aangemaakt die uitgevoerd zal worden als er een

public

method in de

be.g00glen00b.service

package uitgevoerd wordt.

Hiermee wordt ook direct het nut van AOP duidelijk. In plaats van bestaande code te editten kunnen we nu direct de code in de aspect-classes aanpassen. Als we de plaats willen aanpassen waar we deze code willen uitvoeren, dan passen we dit aan in de configuratie.

Maw. de bestaande code wordt niet meer aangepast en indien er in de toekomst nog methodes bijkomen/verdwijnen in de service, dan moeten we geen aanpassing meer maken.

log4j configuratie

Van de Spring configuratie zijn we nu verlost, maar we hebben wel nog een stuk configuratie dat we moeten doen, namelijk de configuratie van log4j. In deze configuratie kunnen we vastleggen wat waar gelogd moet worden en op welke manier.

Uiteindelijk moet

log4j.xml

er zo uit zien:

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE log4j:configuration PUBLIC "-//LOGGER" "log4j.dtd">

<log4j:configuration xmlns:log4j="http://jakarta.apache.org/log4j/">

    <!-- Appenders -->
    <appender name="console" class="org.apache.log4j.ConsoleAppender">
        <param name="Target" value="System.out" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="[%d{dd-MM-yyyy HH:mm:ss}]%-5p: %c - %m%n" />
        </layout>
    </appender>
    <appender name="serviceFile" class="org.apache.log4j.DailyRollingFileAppender">
        <param name="File" value="service.log" />
        <param name="DatePattern" value="'.'yyyy-MM-dd" />
        <layout class="org.apache.log4j.PatternLayout">
            <param name="ConversionPattern" value="[%d{HH:mm:ss}]%-5p: %c - %m%n" />
        </layout>
    </appender>

    <logger name="be.g00glen00b.service">
        <level value="info" />
        <appender-ref ref="serviceFile" />
    </logger>

    <root>
        <priority value="warn" />
        <appender-ref ref="console" />
    </root>
</log4j:configuration>

Wat je hier ziet staan is dat we twee manieren van logging (appenders) hebben. De eerste is het rechtstreeks loggen naar de console en het tweede is de file die we gebruiken om de service te loggen.

Vlak daaronder zie je de link tussen de packages en de manier van logging. Voor de package

be.g00glen00b.service

gaan we loggen naar

serviceFile

, terwijl we voor al de rest naar de console gaan loggen.

Index JSP pagina

Van de configuratie zijn we eindelijk verlost, het enige wat ons nu te doen staat is de JSP pagina  in orde brengen. Deze JSP pagina is dezelfde als we tijdens alle voorgaande tutorials gezien hebben.

<%@ taglib prefix="c" uri="http://java.sun.com/jsp/jstl/core"%>
<%@ taglib prefix="fmt" uri="http://java.sun.com/jsp/jstl/fmt"%>
<html>
<body>
    <h2>${user}</h2>
    <ul>
        <li>Birthday: <fmt:formatDate value="${user.birthDay.time}" type="date" dateStyle="short" /></li>
        <li>Gender:
            <c:choose>
                <c:when test="${user.male}">Male</c:when>
                <c:otherwise>Female</c:otherwise>
            </c:choose>
        </li>
    </ul>
</body>
</html>

Hiermee zijn we dan ook volledig klaar met dit project. De uiteindelijk structuur van het project zou ongeveer hetzelfde moeten zijn als in onderstaande afbeelding.

Builden

Dan staat er ons nu alleen nog maar het uittesten van dit voorbeeld te wachten. Wat we hiervoor doen is het project builden met Maven om daarna het te runnen met Tomcat. Dit hebben we ondertussen al meermaals gedaan, dus hier ga ik niet meer op in.

Als we nu onze browser openen en naar http://localhost:8080/logging-aop-example/steve.html gaan en nadien naar http://localhost:8080/logging-aop-example/bill.html dan zal je merken dat de pagina er totaal hetzelfde uitziet, enkel met andere data.

Hiermee zie je dan ook waarom MVC zo goed is, we hebben maar één JSP pagina die twee keer gebruikt wordt (2 methodes in de controller). We hebben de HTML code dus volledig ontkoppeld van de code die achterliggend moet werken.

Dit was echter niet het doel van deze tutorial. Wat wij willen controleren is ofdat er inderdaad iets gelogd is. Ga hiervoor terug naar Eclipse, selecteer je project en druk op de F5 knop, een bestand met de naam

service.log

zou zichtbaar moeten zijn.

Open dit bestand nu en kijk wat de inhoud is.

Zoals je kan zien wordt alles mooi gelogd. Indien je je afvraagt waarom de methode

getSteveJobs()

zoveel trager is, dit komt omdat de Spring container op dat moment nog wat werk moest verrichten (dit merk je ook in je browser), als je nu deze pagina opnieuw opent zou het resultaat veel minder hoog moeten zijn.

Download project

Download – logging-aop-example.rar (6,4 kB)

Back to tutorialsContact me on TwitterDiscuss on Twitter

Profile picture

Dimitri "g00glen00b" Mestdagh is a consultant at Cronos and tech lead at Aquafin. Usually you can find him trying out new libraries and technologies. Loves both Java and JavaScript.