Hung Build

[garyrussell]

This one has happened a couple of times today...

"Test worker" #12 prio=5 os_prio=31 tid=0x00007f94c62ad000 nid=0x5503 waiting for monitor entry [0x0000700004553000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at com.sun.mail.imap.IMAPFolder.isOpen(IMAPFolder.java)
	- waiting to lock <0x00000007b998c040> (a com.sun.mail.imap.IMAPFolder)
	at org.springframework.integration.mail.MailTransportUtils.closeFolder(MailTransportUtils.java:67)
	at org.springframework.integration.mail.AbstractMailReceiver.closeFolder(AbstractMailReceiver.java:396)
	at org.springframework.integration.mail.AbstractMailReceiver.destroy(AbstractMailReceiver.java:611)
	at org.springframework.integration.mail.ImapMailReceiver.destroy(ImapMailReceiver.java:155)
	at org.springframework.integration.mail.ImapIdleChannelAdapter.destroy(ImapIdleChannelAdapter.java:172)
	at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:258)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:571)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:543)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:1071)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:504)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:1064)
	at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1060)
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1029)
	at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:978)
	- locked <0x00000007b658b748> (a java.lang.Object)
	at org.springframework.test.context.cache.DefaultContextCache.remove(DefaultContextCache.java:207)
	at org.springframework.test.context.cache.DefaultContextCache.remove(DefaultContextCache.java:172)
	at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.closeContext(DefaultCacheAwareContextLoaderDelegate.java:151)
	- locked <0x00000007a02646c0> (a org.springframework.test.context.cache.DefaultContextCache)
	at org.springframework.test.context.support.DefaultTestContext.markApplicationContextDirty(DefaultTestContext.java:148)
	at org.springframework.test.context.support.AbstractDirtiesContextTestExecutionListener.dirtyContext(AbstractDirtiesContextTestExecutionListener.java:69)
	at org.springframework.test.context.support.AbstractDirtiesContextTestExecutionListener.beforeOrAfterTestClass(AbstractDirtiesContextTestExecutionListener.java:148)
	at org.springframework.test.context.support.DirtiesContextTestExecutionListener.afterTestClass(DirtiesContextTestExecutionListener.java:96)
	at org.springframework.test.context.TestContextManager.afterTestClass(TestContextManager.java:488)
	at org.springframework.test.context.junit4.statements.RunAfterTestClassCallbacks.evaluate(RunAfterTestClassCallbacks.java:77)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
	at org.springframework.test.context.junit4.SpringJUnit4ClassRunner.run(SpringJUnit4ClassRunner.java:190)

[artembilan]

I don't know what is going on, but I can assume that we have a race condition:

public void destroy() {
	super.destroy();
	if (this.isInternalScheduler) {
		((ThreadPoolTaskScheduler) this.scheduler).shutdown();
	}
	cancelPing();
}

It definitely looks like we need to cancel ping first and only then go to the regular destroy for closing folder and the service.

[garyrussell]

Here's the pair of threada from another occurrence.

"task-scheduler-9" #2138 prio=5 os_prio=31 tid=0x00007f9460e73800 nid=0x7307 runnable [0x000070000a6e8000]
   java.lang.Thread.State: RUNNABLE
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
	at java.net.SocketInputStream.read(SocketInputStream.java:171)
	at java.net.SocketInputStream.read(SocketInputStream.java:141)
	at com.sun.mail.util.TraceInputStream.read(TraceInputStream.java:126)
	at java.io.BufferedInputStream.fill(BufferedInputStream.java:246)
	at java.io.BufferedInputStream.read(BufferedInputStream.java:265)
	- locked <0x00000007b7342220> (a java.io.BufferedInputStream)
	at com.sun.mail.iap.ResponseInputStream.readResponse(ResponseInputStream.java:103)
	at com.sun.mail.iap.Response.<init>(Response.java:133)
	at com.sun.mail.imap.protocol.IMAPResponse.<init>(IMAPResponse.java:60)
	at com.sun.mail.imap.protocol.IMAPProtocol.readResponse(IMAPProtocol.java:412)
	at com.sun.mail.iap.Protocol.command(Protocol.java:395)
	- locked <0x00000007b73409c0> (a com.sun.mail.imap.protocol.IMAPProtocol)
	at com.sun.mail.imap.protocol.IMAPProtocol.status(IMAPProtocol.java:1403)
	at com.sun.mail.imap.IMAPFolder.getStatus(IMAPFolder.java:1823)
	at com.sun.mail.imap.IMAPFolder.hasNewMessages(IMAPFolder.java:899)
	- locked <0x00000007b732f488> (a com.sun.mail.imap.IMAPFolder)
	at org.springframework.integration.mail.ImapMailReceiver.waitForNewMessages(ImapMailReceiver.java:186)
	at org.springframework.integration.mail.ImapIdleChannelAdapter$IdleTask.run(ImapIdleChannelAdapter.java:277)
	at org.springframework.integration.mail.ImapIdleChannelAdapter$ReceivingTask.run(ImapIdleChannelAdapter.java:249)
	at org.springframework.scheduling.support.DelegatingErrorHandlingRunnable.run(DelegatingErrorHandlingRunnable.java:54)
	at org.springframework.scheduling.concurrent.ReschedulingRunnable.run(ReschedulingRunnable.java:93)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180)
	at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
	at java.lang.Thread.run(Thread.java:748)

"Test worker" #12 prio=5 os_prio=31 tid=0x00007f94621bf000 nid=0x5503 waiting for monitor entry [0x0000700008789000]
   java.lang.Thread.State: BLOCKED (on object monitor)
	at com.sun.mail.imap.IMAPFolder.isOpen(IMAPFolder.java)
	- waiting to lock <0x00000007b732f488> (a com.sun.mail.imap.IMAPFolder)
	at org.springframework.integration.mail.MailTransportUtils.closeFolder(MailTransportUtils.java:67)
	at org.springframework.integration.mail.AbstractMailReceiver.closeFolder(AbstractMailReceiver.java:396)
	at org.springframework.integration.mail.AbstractMailReceiver.destroy(AbstractMailReceiver.java:611)
	at org.springframework.integration.mail.ImapMailReceiver.destroy(ImapMailReceiver.java:155)
	at org.springframework.integration.mail.ImapIdleChannelAdapter.destroy(ImapIdleChannelAdapter.java:172)
	at org.springframework.beans.factory.support.DisposableBeanAdapter.destroy(DisposableBeanAdapter.java:258)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroyBean(DefaultSingletonBeanRegistry.java:571)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingleton(DefaultSingletonBeanRegistry.java:543)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingleton(DefaultListableBeanFactory.java:1071)
	at org.springframework.beans.factory.support.DefaultSingletonBeanRegistry.destroySingletons(DefaultSingletonBeanRegistry.java:504)
	at org.springframework.beans.factory.support.DefaultListableBeanFactory.destroySingletons(DefaultListableBeanFactory.java:1064)
	at org.springframework.context.support.AbstractApplicationContext.destroyBeans(AbstractApplicationContext.java:1060)
	at org.springframework.context.support.AbstractApplicationContext.doClose(AbstractApplicationContext.java:1029)
	at org.springframework.context.support.AbstractApplicationContext.close(AbstractApplicationContext.java:978)
	- locked <0x00000007bf27c168> (a java.lang.Object)
	at org.springframework.test.context.cache.DefaultContextCache.remove(DefaultContextCache.java:207)
	at org.springframework.test.context.cache.DefaultContextCache.remove(DefaultContextCache.java:172)
	at org.springframework.test.context.cache.DefaultCacheAwareContextLoaderDelegate.closeContext(DefaultCacheAwareContextLoaderDelegate.java:151)
	- locked <0x00000007a01d0808> (a org.springframework.test.context.cache.DefaultContextCache)
	at org.springframework.test.context.support.DefaultTestContext.markApplicationContextDirty(DefaultTestContext.java:148)
	at 

The scheduler thread is in a non-interruptible read on the socket.

IMapFolder.hasNewMessages() and isOpen() are synchronized (on the folder); hasNewMessages() won't exit until the read returns some data or the socket is closed.

The java mail API is pretty old - it should have some timeouts 😦

[garyrussell]

So, I think shutting down the scheduler won't help :frown:

[garyrussell]

I think the problem is we need to shut down the test mail server so the getStatus() call from hasNewMessages() will exit.

[garyrussell]

@artembilan Oops - pushed to master directly - please take a look at the commit.

[artembilan]

LGTM