Actually, it hangs sporadically. Just happened again. hmmm.... On Fri, Nov 18, 2011 at 21:25, Guillaume Laforge <glafo...@gmail.com> wrote:
> 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 > > -- 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
