My favorite bug in 2011

Well, the year is still young but I thought to post my favorite bug in 2011 so far. It was a Spring related piece of code which I had added to a legacy application. Can you spot the problem?


<bean id="deactivationDateFormat" class="java.text.SimpleDateFormat" scope="prototype">
<constructor-arg value="yyyy-MM-dd HH:mm:ss" />
</bean>

<bean id="gamePeriodStatsService" scope="prototype"
class="gameperiodstats.impl.GamePeriodStatsServiceImpl">
<property name="dao" ref="gamePeriodStatsDAO"/>
<property name="globalPropertyService" ref="globalPropertyService"/>
<property name="gamePeriodStatsUpdater" ref="gamePeriodStatsUpdater"/>
<property name="gpsDeactivationDate">
<bean factory-bean="deactivationDateFormat" factory-method="parse">
<constructor-arg value="${gps.deactivation.date}" />
</bean>
</property>
</bean>


The change I made to the existing application was to add the gpsDeactivationDate field into the GamePeriodStatsServiceImpl class. I decided to make this a field of type Date and use the SimpleDateFormat class inside the Spring configuration to parse a String value while the ApplicationContext is initialized. The String value has to be in the format yyyy-MM-dd HH:mm:ss and is read from a Java properties file (not shown). The property holding the date as String is called gps.deactivation.date.

We released the code into one of our integration test systems. A few days later, I got assigned a bug in Jira from one of the testers. He copied me a stacktrace from a logfile. As you can see below, there is a lot of noise in the Exception logging from JBoss and Spring. The information you are interested in, is on the last line.


2010-12-31 17:00:34,565 ERROR []
[foo.util.jboss.log.LogInterceptor]
RuntimeException in method: public abstract void foo.util.cron.ejb.CronInvokerLocal.invokeSpring
(java.lang.String,java.lang.String,java.lang.String) throws java.lang.ClassNotFoundException,java.lang.NoSuchMethodException,
java.lang.reflect.InvocationTargetException,java.lang.IllegalAccessException:
[] org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'networkStatsService' defined in class path resource [service/addons/networkstats.applicationContext.xml]: Cannot resolve reference to bean 'gamePeriodStatsService' while setting bean property 'gamePeriodStatsService'; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'gamePeriodStatsService' defined in class path resource [service/addons/gameperiodstats.applicationContext.xml]: Cannot create inner bean 'deactivationDateFormat$created#335fbef1' while setting bean property 'gpsDeactivationDate'; nested exception is org.springframework.beans.factory.BeanCreationException: Error creating bean with name 'deactivationDateFormat$created#335fbef1' defined in class path resource [service/addons/gameperiodstats.applicationContext.xml]: Instantiation of bean failed; nested exception is org.springframework.beans.factory.BeanDefinitionStoreException: Factory method [public java.util.Date java.text.DateFormat.parse(java.lang.String) throws java.text.ParseException] threw exception; nested exception is java.lang.NumberFormatException: multiple points


The system verification department was doing heavy-load testing using bots on several machines. The error showed up only two or three times during the entire day. I started googling for the java.lang.NumberFormatException: multiple points. It turned out it is a weird way of saying you are using SimpleDateFormat from multiple threads on a shared instance. There are tons of articles about SimpleDateFormat not being thread-safe, and I knew about it. I was a bit surprised. The way I had configured my Spring context invokes SimpleDateFormat.parse exactly one time only, at creation of the Application Context.

The problem however, is in the gamePeriodStatsService bean, which was set to scope="prototype" for reasons I don't know. Using this scope would actually always create a new instance of the GamePeriodStatsServiceImpl class every time someone uses applicationContext.getBean inside the code. I figured out that there were a lot of places in the code where getBean was used. Every time a new gamePeriodStatsService bean was created that way, it would use my shared deactivationDateFormat bean - invoking the parse method in the SimpleDateFormat class. The deactivationDateFormat bean is shared because I did not put it in the prototype scope - like you should do. Only stateful beans should use the prototype scope.

We decided to do a semi-lame fix and put the deactivationDateFormat bean also in prototype scope. The proper solution would probably be to remove the prototype scope from all other beans where it was needed. However, I was not brave enough to change this in a legacy systems having 20% test coverage :)