I'm still wondering if that could be something in my codebase also that could be influencing that strange behaviour. My code base has evolved since when it was failing a few days ago, and I've tried running again the build with gradle test, and then it wasn't hanging anymore. Perhaps going back through an older revision I could find a point where it was failing. In my tests, I'm using the unit testing classes of the Google App Engine SDK, which use thread locals and probably other tricks... perhaps it could be launching some daemon threads or something (but I'd expect to see them though in the traces). Could you think of something that a test could be doing, that could prevent Gradle from doing its job? And interesting... something that would not prevent IntelliJ from exhibiting the same behaviour...
Guillaume On Fri, Nov 18, 2011 at 20:03, Luke Daley <luke.da...@gradleware.com> wrote: > > > Begin forwarded message: > > *From: *Guillaume Laforge <glafo...@gmail.com> > *Subject: **Re: [gradle-user] Build hanging at test execution* > *Date: *15 November 2011 10:02:19 PM GMT > *To: *u...@gradle.codehaus.org > *Reply-To: *u...@gradle.codehaus.org > > Hi Adam, > > So with milestone 5, I just did a kill -3 on the two Gradle processes that > I was seeing running with ps aux on my Mac, and here's what I get, below. > I see no trace of my own code there (Gaelyk), nor of the library I'm using > (the Google App Engine SDK), and only see Gradle stuff :-( > > > After looking through the stacks, my only conclusion is that the worker > process never received the stop method call. > > A couple of interesting parts: > > "socket connection at /0:0:0:0:0:0:0:1%0:51890 with /0:0:0:0:0:0:0:1:51874 > receive" prio=5 tid=1018d6000 nid=0x109e4a000 runnable [109e48000] > java.lang.Thread.State: RUNNABLE > at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method) > at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:136) > at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:69) > at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69) > - locked <7f45905c0> (a sun.nio.ch.Util$2) > - locked <7f45905a8> (a java.util.Collections$UnmodifiableSet) > - locked <7f44e1ce8> (a sun.nio.ch.KQueueSelectorImpl) > at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80) > at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84) > at > org.gradle.messaging.remote.internal.inet.SocketConnection$SocketInputStream.read(SocketConnection.java:142) > at java.io.DataInputStream.read(DataInputStream.java:132) > at > java.io.ObjectInputStream$PeekInputStream.read(ObjectInputStream.java:2265) > at > java.io.ObjectInputStream$PeekInputStream.readFully(ObjectInputStream.java:2278) > at > java.io.ObjectInputStream$BlockDataInputStream.readShort(ObjectInputStream.java:2749) > at java.io.ObjectInputStream.readStreamHeader(ObjectInputStream.java:779) > at java.io.ObjectInputStream.<init>(ObjectInputStream.java:279) > at > org.gradle.util.ClassLoaderObjectInputStream.<init>(ClassLoaderObjectInputStream.java:27) > at > org.gradle.messaging.remote.internal.Message$ExceptionReplacingObjectInputStream.<init>(Message.java:151) > at org.gradle.messaging.remote.internal.Message.receive(Message.java:37) > at > org.gradle.messaging.remote.internal.DefaultMessageSerializer.read(DefaultMessageSerializer.java:31) > at > org.gradle.messaging.remote.internal.inet.SocketConnection.receive(SocketConnection.java:75) > at > org.gradle.messaging.remote.internal.DelegatingConnection.receive(DelegatingConnection.java:31) > at > org.gradle.messaging.remote.internal.MessageHub$EeamConnection.receive(MessageHub.java:210) > at > org.gradle.messaging.remote.internal.MessageHub$EndOfStreamConnection.receive(MessageHub.java:195) > at > org.gradle.messaging.remote.internal.AsyncConnectionAdapter$ConnectionReceive.receive(AsyncConnectionAdapter.java:77) > at > org.gradle.messaging.dispatch.AsyncReceive.receiveMessages(AsyncReceive.java:125) > at > org.gradle.messaging.dispatch.AsyncReceive.access$000(AsyncReceive.java:32) > at org.gradle.messaging.dispatch.AsyncReceive$1.run(AsyncReceive.java:74) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl$1.run(DefaultExecutorFactory.java:64) > at > java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) > at java.lang.Thread.run(Thread.java:680) > > > [worker process] - this looks like the message consumer thread, blocked in > a read > > "main" prio=5 tid=101801800 nid=0x100501000 waiting on condition > [100500000] > java.lang.Thread.State: WAITING (parking) > at sun.misc.Unsafe.park(Native Method) > - parking to wait for <7f4572288> (a > java.util.concurrent.CountDownLatch$Sync) > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158) > at > java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:811) > at > java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:969) > at > java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1281) > at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:207) > at > org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:74) > at > org.gradle.api.internal.tasks.testing.worker.TestWorker.execute(TestWorker.java:35) > at > org.gradle.process.internal.child.ActionExecutionWorker.execute(ActionExecutionWorker.java:77) > at > org.gradle.process.internal.child.ActionExecutionWorker.execute(ActionExecutionWorker.java:35) > at > org.gradle..internal.child.ImplementationClassLoaderWorker.execute(ImplementationClassLoaderWorker.java:79) > at > org.gradle.process.internal.child.ImplementationClassLoaderWorker.execute(ImplementationClassLoaderWorker.java:35) > at > org.gradle.process.internal.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:56) > at > org.gradle.process.internal.child.SystemApplicationClassLoaderWorker.call(SystemApplicationClassLoaderWorker.java:38) > at > org.gradle.process.internal.launcher.BootstrapClassLoaderWorker.call(BootstrapClassLoaderWorker.java:52) > at > org.gradle.process.internal.launcher.BootstrapClassLoaderWorker.call(BootstrapClassLoaderWorker.java:33) > at > org.gradle.process.internal.launcher.GradleWorkerMain.run(GradleWorkerMain.java:30) > at > org.gradle.process.internal.launcher.GradleWorkerMain.main(GradleWorkerMain.java:35) > > > [worker process] - this is the “main” thread, it's waiting on a latch that > gets triggered when the worker process sees message to stop. > > Now for the other side… > > "socket connection at /0:0:0:0:0:0:0:1%0:51874 with > /0:0:0:0:0:0:0:1%0:51890 receive" prio=5 tid=101adf000 nid=0x10b3fc000 > runnable [10b3fa000] > java.lang.Thread.State: RUNNABLE > at sun.nio.ch.KQueueArrayWrapper.kevent0(Native Method) > at sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:136) > at sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:69) > at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69) > - locked <7f3ad4598> (a sun.nio.ch.Util$2) > - locked <7f3ad4588> (a java.util.Collections$UnmodifiableSet) > - locked <7f3ad4380> (a sun.nio.ch.KQueueSelectorImpl) > at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80) > at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84) > at > org.gradle.messaging.remote.internal.inet.SocketConnection$SocketInputStream.read(SocketConnection.java:142) > at java.io.DataInputStream.read(DataInputStream.java:132) > at > java.io.ObjectInputStream$PeekInputStream.read(ObjectInputStream.java:2265) > at > java.io.ObjectInputStream$PeekInputStream.readFully(ObjectInputStream.java:2278) > at > java.io.ObjectInputStream$BlockDataInputStream.readShort(ObjectInputStream.java:2749) > at java.io.ObjectInputStream.readStreamHeader(ObjectInputStream.java:779) > at java.io.ObjectInputStream.<init>(ObjectInputStream.java:279) > at > org.gradle.util.ClassLoaderObjectInputStream.<init>(ClassLoaderObjectInputStream.java:27) > at > org.gradle.messaging.remote.internal.Message$ExceptionReplacingObjectInputStream.<init>(Message.java:151) > at org.gradle.messaging.remote.internal.Message.receive(Message.java:37) > at > org.gradle.messaging.remote.internal.DefaultMessageSerializer.read(DefaultMessageSerializer.java:31) > at > org.gradle.messaging.remote.internal.inet.SocketConnection.receive(SocketConnection.java:75) > at > org.gradle.messaging.remote.internal.DelegatingConnection.receive(DelegatingConnection.java:31) > at > org.gradle.messaging.remote.internal.MessageHub$EndOfStreamConnection.receive(MessageHub.java:210) > at > org.gradle.messaging.remote.internal.MessageHub$EndOfStreamConnection.receive(MessageHub.java:195) > at > org.gradle.messaging.remote.internal.AsyncConnectionAdapter$ConnectionReceive.receive(AsyncConnectionAdapter.java:77) > at > org.gradle.messaging.dispatch.AsyncReceive.receiveMessages(AsyncReceive.java:125) > at > org.gradle.messaging.dispatch.AsyncReceive.access$000(AsyncReceive.java:32) > at org.gradle.messaging.dispatch.AsyncReceive$1.run(AsyncReceive.java:74) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl$1.run(DefaultExecutorFactory.java:64) > at > java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) > at java.lang.Thread.run(Thread.java:680) > > > [build process] - looks like the read side of the connection to the > worker, blocked in a read > > "Run Gradle Worker 1 Thread 4" prio=5 tid=101acc000 nid=0x10b2f9000 > runnable [10b2f8000] > java.lang.Thread.State: RUNNABLE > at java.io.FileInputStream.readBytes(Native Method) > at java.io.FileInputStream.read(FileInputStream.java:198) > at > java.lang.UNIXProcess$DeferredCloseInputStream.read(UNIXProcess.java:218) > at > org.gradle.process.internal.ExecOutputHandleRunner.run(ExecOutputHandleRunner.java:46) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl$1.run(DefaultExecutorFactory.java:64) > at > java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) > at java.lang.Thread.run(Thread.java:680) > > > [build process] - unsure what this is > > "Run Gradle Worker 1 Thread 3" prio=5 tid=101acb000 nid=0x10b19c000 > runnable [10b19b000] > java.lang.Thread.State: RUNNABLE > at java.io.FileInputStream.readBytes(Native Method) > at java.io.FileInputStream.read(FileInputStream.java:220) > at > java.lang.UNIXProcess$DeferredCloseInputStream.read(UNIXProcess.java:227) > at java.io.BufferedInputStream.fill(BufferedInputStream.java:218) > at java.io.BufferedInputStream.read1(BufferedInputStream.java:258) > at java.io.BufferedInputStream.read(BufferedInputStream.java:317) > - locked <7f30e37f8> (a java.io.BufferedInputStream) > at java.io.FilterInputStream.read(FilterInputStream.java:90) > at > org.gradle.process.internal.ExecOutputHandleRunner.run(ExecOutputHandleRunner.java:46) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl$1.run(DefaultExecutorFactory.java:64) > at > java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) > at java.lang.Thread.run(Thread.java:680) > > > [build process] - unsure about this one too > > > "Run Gradle Worker 1 Thread 2" prio=5 tid=101ac8000 nid=0x10a8bd000 in > Object.wait() [10a8bc000] > java.lang.Thread.State: WAITING (on object monitor) > at java.lang.Object.wait(Native Method) > - waiting on <7f30e1278> (a java.lang.UNIXProcess) > at java.lang.Object.wait(Object.java:485) > at java.lang.UNIXProcess.waitFor(UNIXProcess.java:115) > - locked <7f30e1278> (a java.lang.UNIXProcess) > at > org.gradle.process.internal.ExecHandleRunner.run(ExecHandleRunner.java:88) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl$1.run(DefaultExecutorFactory.java:64) > at > java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) > at java.lang.Thread.run(Thread.java:680) > > > [build process] - this must be our handle on the worker process > > "Dispatch > org.gradle.api.internal.tasks.testing.processors.RestartEveryNTestClassProcessor@49dc11af" > prio=5 tid=101ab7000 nid=0x109a8d000 waiting on condition [109a8b000] > java.lang.Thread.State: TIMED_WAITING (parking) > at sun.misc.Unsafe.park(Native Method) > - parking to wait for <7f42b39d0> (a > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) > at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:198) > at > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2025) > at > java.util.concurrent.ThreadPoolExecutor.awaitTermination(ThreadPoolExecutor.java:1253) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl.stop(DefaultExecutorFactory.java:89) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl.stop(DefaultExecutorFactory.java:79) > at > org.gradle.process.internal.DefaultExecHandle.waitForFinish(DefaultExecHandle.java:274) > at > org.gradle.process.internal.DefaultWorkerProcess.waitForStop(DefaultWorkerProcess.java:132) > at > org.gradle.api.internal.tasks.testing.worker.ForkingTestClassProcessor.stop(ForkingTestClassProcessor.java:77) > at > org.gradle.api.internal.tasks.testing.processors.RestartEveryNTestClassProcessor.endBatch(RestartEveryNTestClassProcessor.java:60) > at > org.gradle.api.internal.tasks.testing.processors.RestartEveryNTestClassProcessor.stop(RestartEveryNTestClassProcessor.java:54) > at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) > at > sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39) > at > sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25) > at java.lang.reflect.Method.invoke(Method.java:597) > at > org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35) > at > org.gradle.messaging.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24) > at > org.gradle.messaging.dispatch.FailureHandlingDispatch.dispatch(FailureHandlingDispatch.java:29) > at > org.gradle.messaging.dispatch.AsyncDispatch.dispatchMessages(AsyncDispatch.java:132) > at > org.gradle.messaging.dispatch.AsyncDispatch.access$000(AsyncDispatch.java:33) > at org.gradle.messaging.dispatch.AsyncDispatch$1.run(AsyncDispatch.java:72) > at > org.gradle.messaging.concurrent.DefaultExecutorFactory$StoppableExecutorImpl$1.run(DefaultExecutorFactory.java:64) > at > java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) > at > java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) > at java.lang.Thread.run(Thread.java:680) > > > [build process] - this is the worker controller effectively. It *has* > asked the worker to stop > [ForkingTestClassProcessor.stop(ForkingTestClassProcessor.java:77)] which > seems to have been dispatched, now it's waiting for the process to die. > > > So the question is, where is the stop message? The build process has sent > it, but there is no trace of the worker ever receiving it. This leads me to > think that either it never got to the worker, or an error occurred trying > to process it that prevented it from getting to the receive proxy. If the > stop message made it through the messaging infrastructure, it would get to: > > > http://github.com/gradle/gradle/tree/master/subprojects/plugins/src/main/groovy/org/gradle/api/internal/tasks/testing/worker/TestWorker.java#L89 > > This simply means it did not get that far. If it had, that latch would > have been triggered and we wouldn't see the thread in the worker sitting > and waiting on it at > > > http://github.com/gradle/gradle/tree/master/subprojects/plugins/src/main/groovy/org/gradle/api/internal/tasks/testing/worker/TestWorker.java#L74 > > > I think the next thing we need is debug trace for both sides. I'm unsure > how to get debug trace for the worker threads though. > > -- > Luke Daley > Principal Engineer, Gradleware > http://gradleware.com > > -- Guillaume Laforge Groovy Project Manager SpringSource, a division of VMware Blog: http://glaforge.appspot.com/ Twitter: @glaforge <http://twitter.com/glaforge> Google+: http://gplus.to/glaforge
