IllegalMonitorStateException soon after start, polling adapters stop

[vancv786]

I have developed a small spring integration application that reads from several inbound adapters and uses outbound mail adapter to send out email if certain conditions are true. On my development machine (ubuntu 11.10 / tomcat6 / java6_23) it works like a charm and is stable for days (possibly longer).

However, when I install the application on our deployment server (debian sqeeze-sid / tomcat6 /java6_22) soon after start, I get the following exception:

Exception in thread "task-scheduler-1" java.lang.IllegalMonitorStateException
	at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:155)
	at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1262)
	at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:459)
	at java.util.concurrent.DelayQueue.take(DelayQueue.java:205)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:688)
	at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:681)
	at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:1043)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1103)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:603)
	at java.lang.Thread.run(Thread.java:679)

Sometimes this exception comes twice, sometimes only once. Soon thereafter, the polling adapters, which should generate new message each second stop, and application is dead. Anybody recognizes the behavior? What surprises me is that the same .war file works on another, very similar system without any problems.

I've even tried upgrading to tomcat7, but same behavior even there.

Here's my integration context:

<?xml version="1.0" encoding="UTF-8"?>
<!--
  ~ Copyright 2002-2011 the original author or authors.
  ~
  ~ Licensed under the Apache License, Version 2.0 (the "License");
  ~ you may not use this file except in compliance with the License.
  ~ You may obtain a copy of the License at
  ~
  ~      http://www.apache.org/licenses/LICENSE-2.0
  ~
  ~ Unless required by applicable law or agreed to in writing, software
  ~ distributed under the License is distributed on an "AS IS" BASIS,
  ~ WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  ~ See the License for the specific language governing permissions and
  ~ limitations under the License.
  -->

<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:si="http://www.springframework.org/schema/integration"
	xmlns:mail="http://www.springframework.org/schema/integration/mail"
	xmlns:int-stream="http://www.springframework.org/schema/integration/stream"
	xmlns:int-jdbc="http://www.springframework.org/schema/integration/jdbc"
	xmlns:jdbc="http://www.springframework.org/schema/jdbc"
	xsi:schemaLocation="http://www.springframework.org/schema/jdbc http://www.springframework.org/schema/jdbc/spring-jdbc-3.0.xsd
		http://www.springframework.org/schema/integration http://www.springframework.org/schema/integration/spring-integration-2.1.xsd
		http://www.springframework.org/schema/integration/stream http://www.springframework.org/schema/integration/stream/spring-integration-stream-2.1.xsd
		http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-3.0.xsd
		http://www.springframework.org/schema/integration/mail http://www.springframework.org/schema/integration/mail/spring-integration-mail-2.0.xsd
		http://www.springframework.org/schema/integration/jdbc http://www.springframework.org/schema/integration/jdbc/spring-integration-jdbc-2.0.xsd
		http://www.springframework.org/schema/context http://www.springframework.org/schema/context/spring-context-3.0.xsd">

  <context:property-placeholder location="classpath*:META-INF/spring/*.properties"/>
  <context:component-scan base-package="se.celink.ipcheck.integration"/>
  
   <bean class="org.apache.commons.dbcp.BasicDataSource" destroy-method="close" id="dataSource">
        <property name="driverClassName" value="${database.driverClassName}"/>
        <property name="url" value="${database.url}"/>
        <property name="username" value="${database.username}"/>
        <property name="password" value="${database.password}"/>
        <property name="testOnBorrow" value="true"/>
        <property name="testOnReturn" value="true"/>
        <property name="testWhileIdle" value="true"/>
        <property name="timeBetweenEvictionRunsMillis" value="1800000"/>
        <property name="numTestsPerEvictionRun" value="3"/>
        <property name="minEvictableIdleTimeMillis" value="1800000"/>
        <property name="validationQuery" value="SELECT 1"/>
    </bean>

  <si:channel id="input"/>

  <si:inbound-channel-adapter id="inboundChannel" channel="input" ref="loggingSource">
    <si:poller fixed-rate="1000" max-messages-per-poll="100"/>
  </si:inbound-channel-adapter>
   
  <si:channel id="clensedInput"/>
  
  <si:transformer input-channel="input"
	output-channel="clensedInput"
	ref="transformations"
	method="cleanInput"/>

  <si:channel id="clensedInput"/>
	
  <si:filter ref="filters"
  	method="accept"
	input-channel="clensedInput"
	output-channel="filteredClensedInput"/>

  <si:service-activator input-channel="filteredClensedInput"
                       ref="serviceActivators"
                       method="handleIncomingIp">
    <property name="dataSource" ref="dataSource"/>
  </si:service-activator>

  <si:channel id="missingRouters"/>	

  <int-jdbc:inbound-channel-adapter
    channel="missingRouters" data-source="dataSource" query="SELECT * FROM router">
    <si:poller fixed-rate="1000">
      <si:transactional />
    </si:poller>
  </int-jdbc:inbound-channel-adapter>
  
  <si:channel id="mailInput" />  
  <si:channel id="unEnrichedOutboundMail" />
  <si:channel id="outboundMail" />
  

  <si:service-activator id="routerStatusUpdater" 
  	ref="serviceActivators" 
  	method="updateRouterStatus" 
  	input-channel="missingRouters"
  	output-channel="mailInput"/>
  	
  <si:splitter input-channel="mailInput"
	ref="transformations"
	method="splitEmails"
	output-channel="unEnrichedOutboundMail"/>
	 
  <mail:header-enricher input-channel="unEnrichedOutboundMail" output-channel="outboundMail">
  	<mail:to value="vanja.banja@gmail.com" />
	<mail:from value="vanja@celink.se" />
	<mail:subject value="Info from ipCheck" />
  </mail:header-enricher>
 
   <mail:outbound-channel-adapter channel="outboundMail" mail-sender="mailSender" />
  
</beans>

[oleg.zhurakousky]

At first glance it does seems like a JDK bug and looking at you environment you are using later version on your dev machine than your prod.
java6_23 - dev
java6_22 - prod

I would suggest to align them to the same version and see if problem remains

[vancv786]

Hi Oleg

and thanks for an incredibly quick answer! I upgraded java in the prod environment to the latest 1.6 version (1.6.0_32) but that did not solve the problem unfortunately. Then I decided to divide my code in bite-sized chunks and start debugging. Seems like the part that is reading a stream is the problem.

What I'm trying to do is execute tshark-command, which listens to the network interfaces, then parse its output and create messages. Here are the relevant parts of the code:

integration-context:

  
<si:service-activator id="errorLog" input-channel="input" ref="logHandler"/>

<si:channel id="input"/>

<si:inbound-channel-adapter id="inboundChannel" channel="input" ref="loggingSource">
  <si:poller fixed-rate="1000" max-messages-per-poll="10"/>
</si:inbound-channel-adapter>

loggingSource bean (and its helper bean):

@Bean
    public CharacterStreamReadingMessageSource loggingSource() throws FileNotFoundException {
    	CharacterStreamReadingMessageSource messageSource = new CharacterStreamReadingMessageSource(streamReader());
        return messageSource;
    }

    @Bean
    public Reader streamReader() throws FileNotFoundException {
    	LOGGER.debug("Starting the pinging.");
        Reader reader = null;
        try {
        	reader = new InputStreamReader(Runtime.getRuntime().exec("tshark -i venet0:0 -f icmp -l -t ad").getInputStream()); // tshark -i venet0:0 -f icmp -l -t ad
        } catch (Throwable t) {
        	//DO log
        	LOGGER.debug("Failed to start pinging.");
        }
        LOGGER.debug("Started the pinging.");
        return reader;
    }

When I start the server, this works for a 20-30 seconds, and then it stops, sometimes with an exception, sometimes without. Here's the log from the latest run:

INFO: Server startup in 9904 ms
2012-05-02 09:17:45,775 [task-scheduler-2] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Poll resulted in Message: null
2012-05-02 09:17:45,775 [task-scheduler-2] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Received no Message during the poll, returning 'false'
2012-05-02 09:17:46,775 [task-scheduler-1] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Poll resulted in Message: null
2012-05-02 09:17:46,776 [task-scheduler-1] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Received no Message during the poll, returning 'false'
2012-05-02 09:17:47,775 [task-scheduler-2] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Poll resulted in Message: null
2012-05-02 09:17:47,775 [task-scheduler-2] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Received no Message during the poll, returning 'false'
2012-05-02 09:17:48,776 [task-scheduler-2] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Poll resulted in Message: null
2012-05-02 09:17:48,776 [task-scheduler-2] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Received no Message during the poll, returning 'false'
2012-05-02 09:17:49,775 [task-scheduler-2] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Poll resulted in Message: null
2012-05-02 09:17:49,775 [task-scheduler-2] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Received no Message during the poll, returning 'false'
2012-05-02 09:17:50,776 [task-scheduler-2] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Poll resulted in Message: null
2012-05-02 09:17:50,776 [task-scheduler-2] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Received no Message during the poll, returning 'false'
2012-05-02 09:17:51,775 [task-scheduler-2] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Poll resulted in Message: null
2012-05-02 09:17:51,775 [task-scheduler-2] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Received no Message during the poll, returning 'false'
2012-05-02 09:17:52,775 [task-scheduler-4] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Poll resulted in Message: null
2012-05-02 09:17:52,776 [task-scheduler-4] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Received no Message during the poll, returning 'false'
2012-05-02 09:17:53,775 [task-scheduler-4] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Poll resulted in Message: null
2012-05-02 09:17:53,775 [task-scheduler-4] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Received no Message during the poll, returning 'false'
2012-05-02 09:17:54,775 [task-scheduler-2] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Poll resulted in Message: null
Exception in thread "task-scheduler-5" java.lang.IllegalMonitorStateException
        at java.util.concurrent.locks.ReentrantLock$Sync.tryRelease(ReentrantLock.java:127)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.release(AbstractQueuedSynchronizer.java:1239)
        at java.util.concurrent.locks.ReentrantLock.unlock(ReentrantLock.java:431)
        at java.util.concurrent.DelayQueue.take(DelayQueue.java:176)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:609)
        at java.util.concurrent.ScheduledThreadPoolExecutor$DelayedWorkQueue.take(ScheduledThreadPoolExecutor.java:602)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:907)
        at java.lang.Thread.run(Thread.java:662)
2012-05-02 09:17:54,776 [task-scheduler-2] DEBUG org.springframework.integration.endpoint.SourcePollingChannelAdapter - Received no Message during the poll, returning 'false'
May 2, 2012 9:17:54 AM org.apache.catalina.startup.HostConfig checkResources
FINE: Checking context[/ipcheck] redeploy resource /var/lib/tomcat6/webapps/ipcheck.war
May 2, 2012 9:17:54 AM org.apache.catalina.startup.HostConfig checkResources
FINE: Checking context[/ipcheck] redeploy resource /var/lib/tomcat6/webapps/ipcheck
May 2, 2012 9:17:54 AM org.apache.catalina.startup.HostConfig checkResources
FINE: Checking context[/ipcheck] reload resource /var/lib/tomcat6/conf/context.xml
May 2, 2012 9:17:54 AM org.apache.catalina.startup.HostConfig checkResources
FINE: Checking context[/ipcheck] reload resource /var/lib/tomcat6/conf/web.xml

I'm starting to think this is a wrong way to do it :-) Maybe I should be using some kind of event triggering mechanism instead of a polling channel?

Regards,
Vanja

[Gary Russell]

Your approach is fine (or should be); you may get better performance by blocking on readLine(), but only if you expect low-volume.

Oleg's point is this fault is deep in the bowels of the thread pool and is caused when a thread attempts to release a lock it doesn't own. Hence it looks like a JVM problem on that particular platform.

Interestingly, the exception occurs on thread 5, which was not being used by the poller at the time.

You could try giving the poller a dedicated 'task-executor' (<task:executor id="tshark-exec" />) to try to isolate the problem.

[Amol Nayak]

Is your app getting hot deployed by any chance?
As i see this

Checking context[/ipcheck] redeploy resource /var/lib/tomcat6/webapps/ipcheck.war

in your logs and i am assuming the name of your app is ipcheck, it got undeployed and then redeployed.
So possibly during shutdown of the app you got that IllegalMonitorStateException when the app server tried to shutdown the thread pool.

Is there some kind of automatic deployment on your server periodically as this is your dev env? Monitoring the timestamp of the war should give a clue.

Well, i know its an extremely wild guess but, nevertheless a possibility

Another one, irrelevant to the problem, i see this definition twice in your config

<si:channel id="clensedInput"/>

[vancv786]

Hi Guys,

I tried a few more things with very limited (==no) success today, more about that later.

Gary, thanks for you suggestions. I tried giving the poller a dedicated executer, but it did not make any difference (other than constraining the poller to that one executer). Unfortunately, the poller just stopped after a while. As before it sometimes threw the illegalMonitorState-exception, but some other times it just stopped wihtout any exceptions.

Amol, most of the times when I did my tests, I would first stop the tomcat, then kill all remaining tomcat-owned processes (tshark-process will remain active even after the tomcat has been stopped), remove the complete application directory in webapps, copy in the new war file, and then start the tomcat. There have maybe been a few times when I happened to hot deployed a new war, but for the most I made sure everything is new and shiny before testing a new solution. Also, I removed the duplicate channel. Nice catch! However, it made no difference.

Some other things I've tried - I replaced tshark command with "ping 8.8.8.8" in the StreamConfiguration - that one gives a good and steady stream of output. The poller stopped even here after a minute or two. Again, sometimes it would throw exception, sometimes not. In the pure desperation, I decided to change the approach and use a FileReader instead of InputStreamReader, and then just pipe output of tshark to a file. While this worked fine for a minute or two, even this version of the poller stopped.

Now, all of these different approaches are stable and work just fine on my development computer. The stopping happens on our deployment server. The (future) production environment is currently a virtualized debian server with 1G ram, tomcat6, java 1.6.0_32, and I'm running spring integration 2.1.0.

Is there anything I can do to increase logging level on spring-machinery? I've set org.springframework.integration to DEBUG in my log4j config. Could it be the lack of memory? I'm running tomcat with 128M, how much is enough for an application of this dignity? I have a spring roo application running in the same container. Could that be the problem? What will generally get a poller to stop quietly? I've tried listening to and logging messages from errorChannel, but no messages there either.

Thanks guys for all the suggestions so far. Would be so nice to crack this one open.

[CIB]

Hello everyone!
I have the same exception on Glassfish7 and Jboss7.
This is very sad...
Has anyone found a solution for this problem?