How to log request information for future data analysis [Spring MVC + AOP + MongoDB]

Today I would like to speak a little bit about very popular task - logging information about incoming requests in order to have data for future analysis.

Well, this is a common requirement for such areas as E-commerce, social portals, services and so on. From the first look the task is very simple: all you have to do is just log data about incoming requests, responses and other additional data. But when you start thinking deeply about what kind of storage you will be using, what is the requirements for the data analyzer, you will understand that's it's not so trivial and you have to keep in mind a lot of things to build a correct architecture. 

Let's assume that your system is under impressive loading like 1000 requests per second. In such situation the system will produce terabytes of data and probably storing such huge amount of data either in files or in SQL-database is not a good option. So, you might want to ask yourself - which direction should I choose?

I would propose to implement something similar to the following architecture and choose components depending on your specific requirements:

So, imagine that your web server sends log messages first to some broker using JMS or AMQP. You might want to use logstash - a tool for managing events and logs, which I have glossed over until now. I'd highly recommend to take a look at it. Eventually all messages will be stored in a storage - either in NoSQL-storage like MongoDB or in Index-storage like Lucene. Strictly speaking in this case your application is doing its main job without spending additional resources for processing logs. All it does is only sending messages to the "messages bus" to be stored somewhere for future analysis. Choosing storage completely depends on your needs.

In this article I wanna show you simple example how you can achieve it. In order to make it understandable I simplified the architecture a little bit and remove part with Logstash/RabbitMQ (but it's still required for such kind of tasks). So, technologies/frameworks for this small maven project are: Spring/Spring MVC, AOP, MongoDB. Let's start...

I assume that you already have MongoDB installed, up and running. If not - take a look at this tutorial first.

So, as a first step you need to create a simple web-app project. For this purpose you can use maven archetype:

mvn archetype:generate -DgroupId={groupId} -DartifactId={artifactId} -DarchetypeArtifactId=maven-archetype-webapp

Then you have to modify 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/maven-v4_0_0.xsd">
    <modelVersion>4.0.0</modelVersion>
    <groupId>com.vadymlotar.demo</groupId>
    <artifactId>springMongoDB</artifactId>
    <packaging>war</packaging>
    <version>1.0.0</version>
    <name>springMongoDB</name>
   
    <properties>
        <org.springframework-version>3.2.2.RELEASE</org.springframework-version>
        <org.springframework.data-version>1.2.1.RELEASE</org.springframework.data-version>
        <org.aspectj-version>1.6.10</org.aspectj-version>
    </properties>
   
    <dependencies>
        <!-- Spring -->
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-orm</artifactId>
            <version>${org.springframework-version}</version>
        </dependency>

        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-webmvc</artifactId>
            <version>${org.springframework-version}</version>
        </dependency>
       
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-aop</artifactId>
            <version>${org.springframework-version}</version>
        </dependency>

        <dependency>
            <groupId>org.springframework.data</groupId>
            <artifactId>spring-data-mongodb</artifactId>
            <version>${org.springframework.data-version}</version>
        </dependency>
       
        <dependency>
            <groupId>org.springframework</groupId>
            <artifactId>spring-test</artifactId>
            <version>${org.springframework-version}</version>
        </dependency>
       
        <!-- Servlet -->
        <dependency>
            <groupId>javax.servlet</groupId>
            <artifactId>servlet-api</artifactId>
            <version>2.5</version>
            <scope>provided</scope>
        </dependency>
        <dependency>
            <groupId>javax.servlet.jsp</groupId>
            <artifactId>jsp-api</artifactId>
            <version>2.2</version>
            <scope>provided</scope>
        </dependency>
        <dependency>
            <groupId>javax.servlet</groupId>
            <artifactId>jstl</artifactId>
            <version>1.2</version>
        </dependency>           
       
        <!-- AspectJ -->
        <dependency>
            <groupId>org.aspectj</groupId>
            <artifactId>aspectjtools</artifactId>
            <version>1.7.2</version>
        </dependency>
        <dependency>
            <groupId>org.aspectj</groupId>
            <artifactId>aspectjrt</artifactId>
            <version>${org.aspectj-version}</version>
        </dependency>   
       
        <!-- Test -->
        <dependency>
            <groupId>junit</groupId>
            <artifactId>junit</artifactId>
            <version>4.10</version>
            <scope>test</scope>
        </dependency>
    </dependencies>
    <build>
        <finalName>springMongoDB</finalName>
        <plugins>
            <plugin>
                <groupId>org.apache.maven.plugins</groupId>
                <artifactId>maven-compiler-plugin</artifactId>
                <version>2.5.1</version>
                <configuration>
                    <source>1.7</source>
                    <target>1.7</target>
                    <compilerArgument>-Xlint:all</compilerArgument>
                    <showWarnings>true</showWarnings>
                    <showDeprecation>true</showDeprecation>
                </configuration>
            </plugin>
        </plugins>
    </build>
</project>

Do not forget about Spring configuration file:

<?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"
       xmlns:p="http://www.springframework.org/schema/p"
       xmlns:aop="http://www.springframework.org/schema/aop"
       xsi:schemaLocation="http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-3.2.xsd http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context-3.2.xsd http://www.springframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop-3.0.xsd">

    <context:component-scan base-package="com.vadymlotar.demo" />

    <!-- Factory bean that creates the MongoDB instance -->
    <bean id="mongo" class="org.springframework.data.mongodb.core.MongoFactoryBean">
        <property name="host" value="localhost" />
    </bean>
    
    <!-- MongoTemplate for connecting and querying the documents in the database -->
    <bean id="mongoTemplate" class="org.springframework.data.mongodb.core.MongoTemplate">
        <constructor-arg name="mongo" ref="mongo" />
        <constructor-arg name="databaseName" value="test" />
    </bean>

    <!-- Use this post processor to translate any MongoExceptions thrown in @Repository annotated classes -->
    <bean class="org.springframework.dao.annotation.PersistenceExceptionTranslationPostProcessor" />
    
        
    <bean id="jspViewResolver"
          class="org.springframework.web.servlet.view.InternalResourceViewResolver"
          p:prefix="/WEB-INF/jsp/"
          p:suffix=".jsp" />
         
    <!-- Enable Aspects -->     
    <aop:aspectj-autoproxy/>

</beans> 

Create controller which will handle all requests mapped on /home:

@Controller
public class MainController {

    @RequestMapping(value = "/home", method = RequestMethod.GET)
    public ModelAndView show() throws InterruptedException {
        ModelAndView mv = new ModelAndView("/home");
        mv.addObject("message", "Recieved and logged one more request");

        // do some 'real' work
        Random random = new Random();
        int randomDelay = random.nextInt(200);
        Thread.sleep(randomDelay);

        return mv;
    }

}

In order to log requests we need to create POJO class:

public class LogItem {
    @Id
    private String id;
    private String response;
    private long requestDuration;
    private Date date;

    public String getId() {
        return id;
    }
    public void setId(String id) {
        this.id = id;
    }
    public long getRequestDuration() {
        return requestDuration;
    }
    public void setRequestDuration(long requestDuration) {
        this.requestDuration = requestDuration;
    }
    public String getResponse() {
        return response;
    }
    public void setResponse(String response) {
        this.response = response;
    }
    public Date getDate() {
        return date;
    }
    public void setDate(Date date) {
        this.date = date;
    }   
}

This POJO can be extended according to your specific needs.

Then we have to create service class which will be responsible for saving the log data to the MongoDB:

public interface LogItemService {   
    static final String COLLECTION_NAME = "requests";   
    public void addLogItem(LogItem logItem);
}

@Repository
public class LogItemServiceImpl implements LogItemService {

    @Autowired
    private MongoTemplate mongo;

    public void addLogItem(LogItem logItem) {
        initCollectionInMongo();
        // fill out required fields
        logItem.setId(UUID.randomUUID().toString());
        logItem.setDate(new Date());
        // save object in MongoDB
        mongo.insert(logItem, COLLECTION_NAME);
    }

    /**
     * If collection does not exist then creates new collection and registers
     * required indexes
     */
    private void initCollectionInMongo() {
        if (!mongo.collectionExists(COLLECTION_NAME)) {
            // create collection
            DBCollection collection = mongo.createCollection(COLLECTION_NAME);
            // create Time-To-Live Index
            BasicDBObject index = new BasicDBObject("date", 1);
            BasicDBObject options = new BasicDBObject("expireAfterSeconds",
                    TimeUnit.MINUTES.toSeconds(60));
            collection.ensureIndex(index, options);
            // create index for requestDuration column
            index = new BasicDBObject("requestDuration", 1);
            collection.ensureIndex(index);
        }
    }  
}

One of the main steps is to create an advice which will allow us to collect information about incoming request:

@Component
@Aspect
public class RequestLoggerAspect {
   
    @Autowired
    private LogItemService responseItemService;

    /**
     * Advice which allows to do some operations with logging before and after
     * method execution
     *
     * @param joinPoint
     *            joinPoint object describing the calling method
     * @return result of method execution
     * @throws Throwable
     *             an exception could be thrown
     */
    @Around("execution(* com.vadymlotar.demo.controller..MainController*.*(..))")
    public Object logTimeMethod(ProceedingJoinPoint joinPoint) throws Throwable {
        // execution of method started
        StopWatch stopWatch = new StopWatch();
        stopWatch.start();

        Object retVal = joinPoint.proceed();
        // execution of method finished
        stopWatch.stop();
        // prepare string which will appear in the log
        StringBuffer logMessage = new StringBuffer();
        logMessage.append(joinPoint.getTarget().getClass().getName());
        logMessage.append(".");
        logMessage.append(joinPoint.getSignature().getName());
        logMessage.append("(");
        // append args
        Object[] args = joinPoint.getArgs();
        for (int i = 0; i < args.length; i++) {
            logMessage.append(args[i]).append(",");
        }
        if (args.length > 0) {
            logMessage.deleteCharAt(logMessage.length() - 1);
        }

        logMessage.append(")");
        logMessage.append(" execution time: ");
        logMessage.append(stopWatch.getTotalTimeMillis());
        logMessage.append(" ms");
        System.out.println(logMessage.toString());
       
        //save information about request in MongoDB
        LogItem responseItem = new LogItem();
        responseItem.setRequestDuration(stopWatch.getTotalTimeMillis());
        responseItem.setResponse(retVal.toString());
        responseItemService.addLogItem(responseItem);
       
        return retVal;
    }
}
AOP concepts are well explained in Spring documentation. It takes a bit of getting used to, but it's a very powerful thing.

So, now you can deploy the application to some servlet container (e.g. Tomcat or Jetty) and go to http://localhost:8080/%appContext%. Each time you will open this page, a new request information will be put to the MongoDB.

With MongoDB you can analyze the data using MapReduce. For example, in order to know average duration time of request processing you may want to create following map and reduce functions:

// get avg request duration
        String mapFunction = "function(){emit( 'avg',this.requestDuration);}";
        String reduceFunction = "function(key,values){ var total = 0; for(var i = 0; i < values.length; i++) total += values[i]; var mean = total/values.length;return mean;}";

        @SuppressWarnings("rawtypes")
        MapReduceResults<Map> result = mongo.mapReduce(COLLECTION_NAME,
                mapFunction, reduceFunction, Map.class);
        for (Map<String, Double> map : result) {
            requestStatistics.setAvgDuration(map.get("value"));
        }

The completed project contains a lot of examples of how to analyze collected data and you can download project sources here.

In conclusion I would like to say that I do not impose you to choose the technologies for such kind of tasks. You can use whatever you want and whatever is suitable for this task. If you have any comments, remarks or questions don't hesitate to leave your comments below and I'll try to answer.

Thank you for reading and may the force be with you...

Jedis - Java client for Redis

There are huge amount of clients for Redis written in different programming languages.

I've already written some thoughts about Redis and today we will talk about one of the most popular Java client for Redis - Jedis. Jedis is a blazingly small and sane Redis java client and was conceived to be EASY to use.

One of the main pros of Jedis is using all Redis command names as the names of the functions and it really simplifies working with Jedis.

There's no big deal to install Redis server. You just have to download the distributive, unarchive it and run the redis-server. More information you can find here and here.

So, let's assume that you've already installed Redis and able to ping it using redis-cli. It means you are ready to start working with Jedis.

Simple connection to Redis can be established in the following way:

    private static final int PORT = 6379;
    private static final String HOST_NAME = "localhost";
    // single instance
    public static Jedis JEDIS = new Jedis(HOST_NAME, PORT);

It's very simple, isn't it? Another way to establish connection is to use JedisPool - pool of connections:

private void init() {
            GenericObjectPool.Config poolConfig = new GenericObjectPool.Config();
            poolConfig.maxActive = 100;
            poolConfig.maxIdle = 10;
            poolConfig.minIdle = 2;
            poolConfig.maxWait = 100;
            poolConfig.testWhileIdle = true;
            poolConfig.testOnBorrow = true;
            poolConfig.testOnReturn = true;
            poolConfig.minEvictableIdleTimeMillis = 10000;
            poolConfig.timeBetweenEvictionRunsMillis = 5000;
            poolConfig.numTestsPerEvictionRun = 10;
            // create JEDIS pool
            this.jedisPool = new JedisPool(poolConfig, HOST_NAME, PORT);
}


Frankly speaking using the pool is preferable and I'd recommend to use the pool in production. In order to obtain Jedis object from the pool you should write something like this:

    public Jedis getCache() {
        return this.getJedisPool().getResource();
    }

    public void returnCache(Jedis cache) {
        this.getJedisPool().returnResource(cache);
    }

Don't forget about returning the Jedis instance back to the pool after doing some staff with it.

You can write few simple tests to see how Jedis is working and try to play with some Redis commands:

    @Test
    public void testSet() {
        Jedis jedis = connectionFactory.getCache();
        jedis.set("abc", "cba");
        Assert.assertEquals("cba", jedis.get("abc"));
        connectionFactory.returnCache(jedis);
    }

    @Test
    public void testDelete() {
        Jedis jedis = connectionFactory.getCache();
        jedis.set("abc", "cba");
        jedis.del("abc");
        Assert.assertNull(jedis.get("abc"));
        connectionFactory.returnCache(jedis);
    }

    @Test
    public void testAddToList() {
        Jedis jedis = connectionFactory.getCache();
        jedis.rpush("items", "111");
        jedis.rpush("items", "222");
        //check the list size
        Assert.assertEquals(new Long(2), jedis.llen("items"));
        connectionFactory.returnCache(jedis);
    }

As you can see it's very easy to connect to the Redis server using Jedis client.

It's intuitive, clear and simple, but the most important thing is - it's fast. You might want to take a look at Demo project and try to run a test for bulk loading.

You will be impressed. Hopefully, you'll have a fun.

Some thoughts about Redis

In this article I would like to shed light on what the Redis is. I will also explain when you may want to use it from my opinion and say few words about pros and cons of Redis.

I met with this storage few months ago during solving the task which required from me to use a distributed cache. Choosing the key/value store was not so simple task as I thought, because of our specific needs. Besides that the main requirements were stability, availability, scalability and, of course, speed (>60 000 ops/sec). Providing a simple and understandable API and not being a "monster" like MongoDB would also be a plus. So we decided to choose the winner from the following list: Couchbase (Couchbase/Memcached buckets), Memcached, Hazelcast and Redis.

We started our investigation from the Hazelcast, because we've been already using it in many other projects where it demonstrates pretty good results. We wrote simple test application trying to load 20 millions objects to the cache with 10 threads and after putting 7-8 millions objects Hazelcast has gone crazy. Sometimes it happened after loading 10 millions objects, but keeping in mind that we have to store up to 50 millions objects in storage, we decided to switch to the next candidate.

Then we were trying to see how both data buckets provided by Couchbase are working. From the first look Couchbase is awesome. It has a lot of different options like clustering, auto-failover, map/reduce and persistence for Couchbase buckets, asynchronous operations and many other things. Sounds good, yeah? Then we run our test and it quickly put everything in its place. The Couchbase Admin page showed incredible numbers for remote connection 50 000-60 000 ops/sec and >100 000 ops/sec for local connection, however only 40-60% of all data we were trying to load to the bucket was there in the end of the test. All other operations failed because of timeout. The Couchbase experts explained it by the fact that we didn't check the result of set/add operations. Yes, it was true, because when you add this check it means you are using synchronous operations instead of asynchronous and performance degradation is very impressive (<1000 ops/sec for remote connection and 20 000 - 30 000 ops/sec for local connection). So, taking into account that our distributed cache must handle huge amount of operations during bulk load correctly and in a very fast way, we decided to find luck somewhere else.

The next step was to choose between Memcached and Redis. It was our last hope... 

Memcached - free & open source, high-performance, distributed memory object caching system - was developed very long time ago and is very popular till now. It has only one disadvantage - it's a simple key/value store without an ability to work with different data structures. So, if you know that you won't need to store, for example, Sorted Set in the cache for sure, you might want to choose Memcached. Redis is a little bit more than that...

Thus, Redis became our choice and, fortunately, it meets all our needs. 

Redis is an open source, BSD licensed, advanced key-value store. It is often referred to as a data structure server since keys can contain strings, hashes, lists, sets and sorted sets.

You can do "almost" the same operations with strings, lists, sets as you usually do working with simple String, ArrayList or HashSet in Java. Unfortunately, "almost" means not really, pardon the pun. For example, there is no ability to check whether the list contains some element or not. Strange? Yes, it's very strange. You wanna another "funny" example? Well, it's simple - you can get a range of elements from the sorted set but cannot do that using a regular one. Let's imagine that you don't want to use different data structures and want to use Redis as a simple key/value store, like a simple map. Another surprises will appear, be sure. For example it's not so simple to iterate over this map or get the ranges. I would say that it's even impossible to do without creating an additional key where you will store a list or a set of keys. What do you think about ability to specify the DB not by name and just by index? Why it's like that? - I have no idea. You can read about all operations provided by Redis here.

But let's finish telling bad things about Redis, because I have a feeling that you already don't like it. The good news are - it's stable, you can configure master-slave communication. It's very fast - some benchmarks say that it's even faster than memcached, but I would say that it's pretty much the similar. If you have enough memory you can implement missed functionality by creating additional lists, sets and so on. It also has a very good community. So basically it can do everything you might want to do with data in the cache and my suggestion is to play with it a little bit and you will understand what's what. Don't give up.

In the next article I will provide small example demonstrating how to use Jedis - Java client for Redis.

Notice that all tests in this article have been run on a specific environment and you probably will get different results testing all these storages on your custom environment.

Few words about me and this blog

Greetings. If you might know I've just moved to Germany and started working here as a Java Software Engineer at Rakuten Deutchland GmbH. So, the new epoch for me has started...

Before it happened, I've been working on different positions at Intersog and Lohika - software companies located in Ukraine. Frankly speaking it was an excellent experience and great time. I was lucky to work on several startups as well as on a "real" enterprise HP product which is called Application Lyfecycle Management. During this period I was able to meet, work  and learn from the engineers which can be called a true GURU.
 

However, I feel that now is my turn to share the knowledge and through this blog I will try to provide as many interesting thoughts and articles as I can. Hope it'll help somebody.

I would also want to take a moment and talk about what kind of frameworks and technologies I like and usually use. My love number one is Spring framework and all infrastructure around it. I would recommend to take a look at the following blog SpringByExample. So, I think there are going to be several posts about Spring added in coming weeks, at least I will try to write something interesting. It was a time when I had written several JSF applications and to be honest I like it much more than GWT or so on. Of course I cannot live without utility libraries developed by apache and google. In addition to what I've already said I would add ORM frameworks, caching libraries, NoSQL and many-many other technologies. Someday this blog will contain articles about all these staff and even more.

Small announcement: the first technical article would be - "Some thoughts about Redis". To be continued...