Easy testing SLAs on distributed components with grep4j

So your distributed architecture looks something like the picture below and you just have received a requirement from the business to make sure that the SLAs of the messages sent by the Producer and then traveling to the downstream systems (consumers) must be fast and never slower than 400 milliseconds.

Requirement says :
The Latency of a message sent from the Producer to any of the Consumers should be never slower than 400 milliseconds.

Sounds familiar? To me yes, and experience taught me that if I want to protect the SLAs in the future, I need as well to automate the test in order to not introduce bottlenecks that then increase the latency of the messages.

But how to do it? Producer and Consumers are in separate machines and some of the consumers are not written in Java.
Also, between the producer and the consumers there is a Queue (or web-service or RMI or an ESB or another component or whatever), so things are not getting easier for me to test.

Well, all components write logs in a similar way, so why not using logs as a data to test?

For example these are 2 sample logs, one from the producer firing a message (id 1546366) and the other from one of the consumer receiving the message (id 1546366):

Producer logs 

......

2013-02-19 10:09:05,795 INFO  [org.grep4j.demo.input.core.InputCoreMessageSender] (pool-19-thread-9) Input::MessageSender::Message(1546366) Sent Successfully

......

Consumer logs

.....

2013-02-19 10:09:06,161 INFO  [org.grep4j.demo.handler.bean.mdb.SingleDestPacketHandler] (Thread-62314 (HornetQ-client-global-threads-989457197)) Handler::Packet::Message(1546366) Received::PacketId(982336426)::State(NORMAL)::Dest(CONSUMER4, 1)::DataLevel(EVENT, 7)::Op(CREATE, C)::GlobalId(1546366)::Priority(1)::Src(GUI, 1::Ids(EventId=1546366,SFBId=1546366,isBirType=false,inBir=false))

.....

And this is how my automated performance test looks like using Grep4j :

package com.gdg.grep4j.demo;
import static com.gdg.grep4j.demo.profiles.Profiles.consumer1;
import static com.gdg.grep4j.demo.profiles.Profiles.consumer2;
import static com.gdg.grep4j.demo.profiles.Profiles.consumer3;
import static com.gdg.grep4j.demo.profiles.Profiles.producer;
import static com.gdg.grep4j.demo.services.TimeService.extractTime;
import static org.grep4j.core.Grep4j.constantExpression;
import static org.grep4j.core.Grep4j.grep;
import static org.grep4j.core.fluent.Dictionary.on;
import static org.hamcrest.CoreMatchers.is;
import static org.hamcrest.number.OrderingComparison.lessThan;
import static org.junit.Assert.assertThat;
import org.grep4j.core.result.GrepResults;
import org.testng.annotations.BeforeTest;
import org.testng.annotations.Test;
@Test
public class MessageDistributionPerformanceTest {


        private static final long MAX_ACCETABLE_LATENCY = 400L;

        private long producerTime = 0;

        private GrepResults consumersResults;
        
        @BeforeTest
        public void triggerMessageDispatcher() {
                System.out.println("Producing and firing a Message(1546366) to downstream systems...");
        }
        
        @BeforeTest
        public void extractProducerTime() {
                
                GrepResults producerResult = grep(constantExpression("Message(1546366) Sent Successfully"),     on(producer));
                producerTime = extractTime(producerResult.toString());
        }
        
        @BeforeTest
        public void grepConsumerLogs() {
                                
                consumersResults = grep(constantExpression("Message(1546366) Received"),
                                on(consumer1, consumer2, consumer3));
        }

        public void testConsumer1Latency() {
 
                long consumer1Time = extractTime(consumersResults.filterOnProfile(consumer1).toString());
                assertThat((consumer1Time - producerTime),
                                is(lessThan(MAX_ACCETABLE_LATENCY)));
        }

        public void testConsumer2Latency() {

                long consumer2Time = extractTime(consumersResults.filterOnProfile(consumer2).toString());
                assertThat((consumer2Time - producerTime),
                                is(lessThan(MAX_ACCETABLE_LATENCY)));

        }

        public void testConsumer3Latency() {

                long consumer3Time = extractTime(consumersResults.filterOnProfile(consumer3).toString());
                assertThat((consumer3Time - producerTime),
                                is(lessThan(MAX_ACCETABLE_LATENCY)));

        }
}

A profile is the grep target context, in my case all the profiles are remote machines (for a better understanding of Profiles see Grep4j page).

TimeService is just a simple service class extracting the time in the logs.

package com.gdg.grep4j.demo.services;
import java.text.ParseException;
import java.text.SimpleDateFormat;
import java.util.Date;
import java.util.TimeZone;
import java.util.regex.Matcher;
import java.util.regex.Pattern;
public class TimeService {

        private static final Pattern timePattern = Pattern
                        .compile("([0-9][0-9][0-9][0-9])-([0-9][0-9])-([0-9][0-9]) ([0-9][0-9]|2[0-3]):([0-9][0-9]):([0-9][0-9]),([0-9][0-9][0-9])");

        public static long extractTime(String text) {
                Matcher lm = timePattern.matcher(text);
                if (lm.find()) {
                        SimpleDateFormat sdf = new SimpleDateFormat(
                                        "yyyy-MM-dd HH:mm:ss,SSS");
                        sdf.setTimeZone(TimeZone.getTimeZone("UTC"));

                        String inputString = lm.group();

                        Date date = null;
                        try {
                                date = sdf.parse(inputString);
                        } catch (ParseException e) {
                                e.printStackTrace();
                        }
                        return date.getTime();

                } else {
                        throw new IllegalArgumentException("timePattern not found");
                }
        }
}

In few simple lines of code I have my extremely flexible test (I can test anything that was produced in the logs) .

For the full code : https://github.com/marcocast/grep4j-gdg.git

A simple way to test distributed applications

So, testing distributed applications is not easy, we all know it.
Too many variants to take in considerations which usually lead to an high instability of the tests.

Let say we have a front end application sending messages to a distribution engine which then forward the messages to other remote destinations. Sounds familiar?

OK so, how you test that messages travelling correctly trough all the predefined servers?

What if I want to keep my tests independent from any integration framework?

My solution is in the logs.
Why not rely on the logs to prove that your application is working as expected?

Logs are often underrated for performance/acceptance/smoke tests, but if correctly written, they can provide all the information you need to measure the status of your software at any point of its execution.

Testing relying on logs is a non intrusive way to test and no performances or anything will be affected. Applying this concept to an hypothetical integration test it's easy (at least in UNIX environments :) ), thanks to libraries like Grep4j:

import static org.grep4j.core.Grep4j.grep; import static org.grep4j.core.Grep4j.regularExpression; import static org.grep4j.core.fluent.Dictionary.on; import static org.grep4j.core.fluent.Dictionary.executing; ... @Test public void aCreateMessageShouldPassThroughAllTheFinalDestinations() {   List profiles =  Arrays.asList(distributionServerLog(),                                  destination1ServerLog(),                                  destination2ServerLog(),                                  destination3ServerLog()); assertThat(executing(grep(regularExpression("MessageId(.*)Received"), on(profiles))).totalLines(), is(4)); }

As you can see, in a very simple way you have an efficient end-to-end test across different machines.

I think this approach is also a good option when you want to build acceptance or regression tests around legacy applications. You can treat your legacy app as a black box and just test the expected output in the log. 

Finally, I reckon this way of test will force the developers to standardize and uniform the way to log in the code which is always good :)

Fluent mirror methods

How important is the readability of the code you write?

I think very important, probably one of the key to success in delivering good working and maintainable software.

This article is about a simple technique to help you and the people working on your code to fast understand what's happening.

I called this technique fluent mirror methods, and usually I wrap all these kind of methods in a single class called Dictionary. 

A fluent mirror method is a simple static method returning the same object passed. For example:

public static <T> T executing(T type) {
                return type;
        }

You can use these methods as follows:

import static org.grep4j.core.Grep4j.grep; 

import static org.grep4j.core.fluent.Dictionary.on;
import static org.grep4j.core.fluent.Dictionary.executing;
import static org.grep4j.core.fluent.Dictionary.expression;
import static org.grep4j.core.fluent.Dictionary.with;
...

assertThat(executing(grep(with(expression("Marco")), on(profile))).totalLines(), is(1));