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