India 2015 - Bike Ride 1

Srivilliputtur lies on the foothills of the Western Ghats mountain range, which known to be a hotspot for biodiversity. It is close to a wildlife sanctuary for the endangered grizzled giant squirrel, which is locally known as Senpaga Thoppu. It is about 10k from my house.  On Aug 6th, Maven, Lydia and I went on a bicycle ride on the road that leads to this sanctuary. Within a kilometre of the ride, the intense noisy traffic disappears and you start to see rural life and wilderness. We rode about 2k before returning back. Lydia took all these photos.

Path to Senpaga Thoppu (as you leave Srivi). Notice how little traffic there is.

Cemetery. Lydia commented how even the cemeteries are crowded here.

A herd of goats. The herder said he has about 200 goats.

Stopped alongside a reservoir before heading back. This pool of water is a hotspot of bird watching, but don't be surprised if you see people using it as their public washroom.

The traffic on this road is mostly from people who work at the farms near by.

Returning back home (my street). My house is on the right closer to the temple on the middle of the road.

India 2015 - Arrival

Our trip preparation started a week before our departure and went quite smooth. We left Ottawa on Oct 30th for Chennai via Toronto and Frankfurt. The plane ride was as awesome as it could be with a toddler. We arrived in Chennai on Nov 1st and stayed there till the 3rd. Chennai was crazier than I thought it would be. It had grown exponentially for the past few decades and like all other cities in India, the infrastructure development lags quite a bit behind the commercial growth (and population). If you are a tourist, Chennai is a good place to start your exposure to India as you can get all the amenities, ranging from cushy toiler paper to mega shopping malls and over-the-top luxury. We are not tourists and our intent for a stopover in Chennai before heading to my hometown, Srivilliputtur (Srivi), was to reconnect with family and to rest. Indeed, we had a great time in Chennai but the crazy traffic was getting to us. We left Chennai for Srivi on the Pothigai Express train (overnight journey covering roughly 600km) on Nov 3rd.  We had reserved seats (+ beds) on coach A1 (AC, 2 tier). The train journey was rough as we had to share our narrow hard bed with a toddler, who was jet-lagged and over-stimulated. But one thing I love about Indian trains is the ability to open the door while moving and peek out to get some fresh air. So I did in the morning. It had rained. It was lush greenery and pools of water everywhere. It was quite awesome to experience cool morning breeze. We could taken a flight from Chennai to Madurai, which is about 80km from Srivi but you don't get experience a country over the air.

We reached Srivi at around 7 AM on Nov 4th. Here are some shots I took as we took an auto-rickshaw from the station to the our home.

Lydia is so excited to be here that you can't see how jet-lagged she is.

Road to my home in Srivi. You have no idea how crazy this road will be just an hour.

School kids starting their day

Executable Specifications

In my previous job, I was given the opportunity to use ScalaTest. It is a library to write and test software specifications. In other words, you can use it to write "executable specifications". Recently, I showed off ScalaTest at my current job. Here is the summary of it.

Suppose we have need table that has the following specification:
Creation:
 - first column must be "Col1"
Addition:
 - add a row (support variable row length)
 - can't add an empty row
...  etc
Retrieval:
 - error if you attempt to get values for a column that doesn't exist
 - empty array if no values for a column
... etc

Here is the ScalaTest code for the specification:

import org.scalatest._

class MyTableSpec extends FlatSpec with Matchers {
 
  behavior of "Addition"
 
  it should "allow you to add a row of values " in {
    val myTable = new MyTable("Col1", "Col2", "Col3")
    myTable.add(1, 100, 100)

    myTable.getColumn("Col1") should be (Array(1))
    myTable.getColumn("Col2") should be (Array(100))
    myTable.getColumn("Col3") should be (Array(100))
  }
 
  it should "allow you to add a row of length less than the number of columns" in {
    val myTable = new MyTable("Col1", "Col2", "Col3")
    myTable.add(1, 100)
  
    myTable.getColumn("Col1") should be (Array(1))
    myTable.getColumn("Col2") should be (Array(100))
  }
 
  it should "throw AssertionError if you attempt to add an empty row" in {
    val myTable = new MyTable("Col1", "Col2", "Col3")
   
    a [AssertionError] should be thrownBy {
      myTable.add()
    }
  }
 
  behavior of "Retrieval"
 
  it should "give you a set of row values for time t" in {
    val myTable = new MyTable("Col1", "Col2", "Col3")
    myTable.add(1, 100, 100)
   
    myTable.getRow(1) should be (Array(1,100,100))
  }
 
  it should "give you an empty array (of type Int) if you retrieve values for a column that doesn't have any" in {
    val myTable = new MyTable("Col1", "Col2", "Col3")
    myTable.add(1, 10)
  
    myTable.getColumn("Col3") should be (Array.empty[Int])
  }
 
  it should "throw NoSuchElementException if you attempt to retrieve values for a column that does not exist" in {
    val myTable = new MyTable("Col1", "Col2", "Col3")
    myTable.add(1, 10, 10)
   
    a [NoSuchElementException] should be thrownBy {
      myTable.getColumn("Col4")
    }
  }
 
  it should "throw AssertionError if you attempt to insert a row with a non-unique value for time " in {
    val myTable = new MyTable("Col1", "Col2", "Col3")
    myTable.add(1, 10, 10)
   
    a [AssertionError] should be thrownBy {
      myTable.add(1, 10, 10)
    }
  }
 
  behavior of "Creation"
 
  it should "throw AssertionError if the first column is not \"Col1\"" in {
    a [AssertionError] should be thrownBy {
      new MyTable("Col1")
    }
  }
 
}
 In addition to unit style testing, you can use ScalaTest to write clear, concise and descriptive tests (which leads to robust software).

At the core of ScalaTest is its Domain Specific Language (DSL) for testing software, and Scala, being flexible and extensible, is a natural fit.

If you are interested in the implementation of this table, contact me.

ArrayIndexOutOfException when creating a bean using Spring 3.0.5

I found a bug recently when using Spring 3.0.5, which appears to be fixed in 4.0.5. Here are the details.

If you have a class that has a parameterized constructor and also has a method that uses a lambda expression (introduced in Java 8), then a ArrayIndexOutOfException occurs when creating a bean for that class.

Here is the stack trace:

Exception in thread "main" java.lang.ArrayIndexOutOfBoundsException: 17676
    at org.springframework.asm.ClassReader.readClass(Unknown Source)
    at org.springframework.asm.ClassReader.accept(Unknown Source)
    at org.springframework.asm.ClassReader.accept(Unknown Source)
    at org.springframework.core.LocalVariableTableParameterNameDiscoverer.inspectClass(LocalVariableTableParameterNameDiscoverer.java:114)
    at org.springframework.core.LocalVariableTableParameterNameDiscoverer.getParameterNames(LocalVariableTableParameterNameDiscoverer.java:86)
    at org.springframework.beans.factory.support.ConstructorResolver.autowireConstructor(ConstructorResolver.java:193)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.autowireConstructor(AbstractAutowireCapableBeanFactory.java:1003)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBeanInstance(AbstractAutowireCapableBeanFactory.java:907)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.doCreateBean(AbstractAutowireCapableBeanFactory.java:485)
    at org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory.createBean(AbstractAutowireCapableBeanFactory.java:456)
    at org.springframework.beans.factory.support.AbstractBeanFactory$1.getObject(AbstractBeanFactory.java:291)
    at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.getSingleton(DefaultSingletonBeanRegistry.java:222)
    at org.springframework.beans.factory.support.AbstractBeanFactory.doGetBean(AbstractBeanFactory.java:288)
    at org.springframework.beans.factory.support.AbstractBeanFactory.getBean(AbstractBeanFactory.java:190)
    at org.springframework.beans.factory.support.DefaultListableBeanFactory.preInstantiateSingletons(DefaultListableBeanFactory.java:580)
    at org.springframework.context.support.AbstractApplicationContext.finishBeanFactoryInitialization(AbstractApplicationContext.java:895)
    at org.springframework.context.support.AbstractApplicationContext.refresh(AbstractApplicationContext.java:425)
    at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:139)
    at org.springframework.context.support.ClassPathXmlApplicationContext.<init>(ClassPathXmlApplicationContext.java:83)
    at LambdaSpringTest.main(LambdaSpringTest.java:9)

Here are the reproduction steps:

1. A sample class

import java.util.List;

public class LambdaSpring
{
    public LambdaSpring(){}
   
    public LambdaSpring(String arg1, String arg2){}
   
    public void method(List<Object> list)
    {
        list.stream().forEach(t -> System.out.println(t));
    }
}

2. Spring Bean configuration

<bean id="lambdaspring" class="LambdaSpring">
 <constructor-arg value="blabla"></constructor-arg>
 <constructor-arg value="blabla2"></constructor-arg>
</bean>

3. Running this main method will result in ArrayIndexOutOfException

import org.springframework.context.support.ClassPathXmlApplicationContext;

public class LambdaSpringTest
{
    public static void main(String[] args)
    {
        ClassPathXmlApplicationContext context = new ClassPathXmlApplicationContext("lamdaspring.xml");
        LambdaSpring tmp = (LambdaSpring) context.getBean("lambdaspring");
    }
}

This issue appears to be fixed in Spring 4.0.5 (possibly earlier as well), but if you can't upgrade for some reasons, here are some workarounds:

I found that if you don't use the parameterized constructor, then you don't get this exception. Also, if you replace the lambda expression with the equivalent boilerplate code (i.e., implement Consumer interface), then you don't get this exception.

Properly handling equals method

Some time ago, I had to troubleshoot a nasty memory leak problem around connection pooling, where JVM heap space kept growing despite no incoming traffic. We were using the Apache Commons Pools library to manage the pool but we also extended to customize the validation of pooled object to ensure only pooled objects of less than certain age were kept. A ConcurrentHashMap instance was used to store the pooled object and its creation time, so when it was time to validate a pooled object, we would get the object from this hash map and check its age. A bug in this logic resulted in the hash map growing to heap space exhaustion. In particular, it was bug in equals method. In this blog, I summarize what I learnt:

Suppose:

You have an interface and a class that implements it;

    public interface SomeInterface{}

    public class ObjectP implements SomeInterface
    {
        public String str;
       
        public ObjectP(String str)
        {
            this.str = str;
        }
       
        @Override
        public String toString()
        {
            return str;
        }
       
        public String toUpperCase()
        {
            return str.toUpperCase();
        }
       
        @Override
        public boolean equals(Object o)
        {
            System.out.println("ObjectP.equals invoked");
            return str.equals(((ObjectP)o).str);
        }
    }

You have an TestInvocationHandler that acts a proxy to ObjectP:

       public class TestInvocationHandler<T> implements InvocationHandler 
   {
       
        T t = null;
       
        public TestInvocationHandler(T t)
        {
            this.t = t;
        }

        @Override
        public Object invoke(Object arg0, Method method, Object[] args)
                throws Throwable {
            if (method.getName().equals("equals")) {
               
                System.out.println("equals method invoked. args[0].getClass()=" + args[0].getClass());
                System.out.println("this object = "  + this);
              boolean result = this.equals(args[0]);
                System.out.println("equals method returned " + result);
                return result;
            } else if (method.getName().equals("hashCode")) {
                return this.hashCode();
            } else if (method.getName().equals("toString")) {
                return t.toString();
            } else {
                return invokeInternal(method, args);
            }
        }

        private Object invokeInternal(Method method, Object[] args) throws Exception, IllegalArgumentException, InvocationTargetException
        {
            return method.invoke(t, args);
        }
    }

You create a Proxy class as follows:
       
        TestInvocationHandler<ObjectP> h1 = new TestInvocationHandler<ObjectP>(new ObjectP("hello"));
        TestInvocationHandler<ObjectP> h2 = new TestInvocationHandler<ObjectP>(new ObjectP("world"));
               
        Proxy p1 = (Proxy) Proxy.newProxyInstance(ObjectP.class.getClassLoader(), new Class[] { SomeInterface.class }, h1);

What should p1.equals(p1) be? The answer is false. Here is the output of p1.equals(p1)

equals method invoked. args[0].getClass()=class com.sun.proxy.$Proxy0
this object = ProxyClassTest$TestInvocationHandler@1b16e52
equals method returned false


That is, this.equals(args[0])is equivalent of saying TestInvocationHandler.equals(Proxy) which always returns false.

This bug resulted in ConcurrentHashMap.remove(object) to do nothing which resulted in the hash map to grow till the heap space was full.

The fix was simple; args[0].equals(this) instead of this.equals(args[0]) so that we do  RetryingInvocationHandler.equals(RetryingInvocationHandler):

if (method.getName().equals("equals")){  
        System.out.println("equals method invoked. args[0].getClass()=" + args[0].getClass());
        System.out.println("this object = "  + this);
        boolean result = args[0].equals(this);
        System.out.println("equals method returned " + result);
        return result;
} 

Useful logging mechanism: Log Markers

In my previous post, I showed a simple example about MDC. In this post, I discuss the use of log markers (http://logback.qos.ch/manual/filters.html). Like MDC filters, marker filters are also "turbo filters" in Logback. Both these filters get triggered after a log event is created but before the log appender(s) are invoked. So they are a good choice for high-performance logging. While MDC filters are ideal to trace the path of a request, log marker filters are good for logging certain use cases.

Suppose we want to log the stack trace for user authentication failures (incorrect userid, incorrect password, account locked, db failure, etc) . Typically, the stack traces are logged in DEBUG level so they don't fill your production logs. So what we want is the ability to log the stack trace only for user authentication failures.

Log markers come handy here. You can use a log marker (say LOG_STACKTRACE_USER_AUTH_FAILURE) like this:

Marker logMarker = MarkerFactory.getMarker(LOG_STACKTRACE_USER_AUTH_FAILURE);
log.debug(logMarker, exception);

And in your logback.xml:

 <turboFilter class="ch.qos.logback.classic.turbo.MarkerFilter">
    <Marker>LOG_STACKTRACE_USER_AUTH_FAILURE</Marker>
    <OnMatch>ACCEPT</OnMatch>
  </turboFilter>

Irrespective of the global logger level you may defined*, this will allow your software to log stack trace to an appender when a log event with a marker called "LOG_STACKTRACE_USER_AUTH_FAILURE" is created.

* This behaviour is particular to ch.qos.logback.classic.turbo.MarkerFilter implementation.

Here is a good stackoverflow discussion on uses for MDC and log markers: http://stackoverflow.com/questions/4165558/best-practices-for-using-markers-in-slf4j-logback

Useful logging mechanism: Mapped Diagnostic Context (MDC) in Logback

Quite often, enterprise-level web applications need to log sufficient information for troubleshooting problems but logging can be resource intensive and log analysis can be time consuming, especially if the application in question is deployed in production serving high volume of requests. Mapped Diagnostic Context (MDC)  in Logback is a useful logging mechanism that gives us the ability to select what to log. In this post, I describe a simple use case to demonstrate its usefulness.

If you are using Maven, you need the following dependencies in your pom.xml for this demo:

<dependency>

 <groupId>org.slf4j</groupId>

 <artifactId>slf4j-api</artifactId>

 <version>1.7.5</version>

</dependency>

<dependency>

 <groupId>ch.qos.logback</groupId>

 <artifactId>logback-core</artifactId>

 <version>1.0.13</version>

</dependency>

<dependency>

 <groupId>ch.qos.logback</groupId>

 <artifactId>logback-classic</artifactId>

 <version>1.0.13</version>

</dependency>

In the following example, we would like "Starting app" and "Finishing app" statements to be logged. We would also like to log "Hello Parthy" but not "Hello Fred", both of which are DEBUG-level log statements. 

Using MDC:

    public static void main( String[] args )

  {

        Logger logger = LoggerFactory.getLogger("personal.tests.logback");

        

        logger.info("Starting app.");

        String username = "Parthy";

        MDC.put("username",  username);

        logger.debug("Hello {}", username);

        MDC.remove("username");

        username = "Fred";

        MDC.put("username",  username);

        logger.debug("Hello {}", username);

        MDC.remove("username");

        

        logger.info("Finishing app.");

  }

logback.xml (using MDCFilter that is shipped with logback):

<configuration>

 <turboFilter class="ch.qos.logback.classic.turbo.MDCFilter">

  <MDCKey>username</MDCKey>

  <Value>parthy</Value>

  <OnMatch>ACCEPT</OnMatch>

 </turboFilter>

 <appender name="console" class="ch.qos.logback.core.ConsoleAppender">

  <encoder>

   <pattern>%date [%thread] %-5level %logger - %msg%n</pattern>

  </encoder>

 </appender>

 <root level="INFO">

  <appender-ref ref="console" />

 </root>

</configuration>

Setting the OnMatch value in the turboFilter to DENY will prevent "Hello Parthy" getting logged. In this case, "Hello Fred" will also not be logged because the root logger level is INFO and "Hello Fred" is logged at DEBUG level.

To use MDC effectively, developers should put the customer support hat and ask how can I trace an individual request amidst tens or hundreds of thousands of request with minimal noise in the logs. Find out how requests are identified (request id, session id, user name etc) and use those as MDC keys. You might say that such filtering is CPU intensive. Actually, logback's turboFilter is intended for high performance.

Interested? Read more here: http://logback.qos.ch/manual/filters.html