Possible racing issue in StagedMultipleSPFExecutor or dnsjnio
-------------------------------------------------------------
Key: JSPF-65
URL: https://issues.apache.org/jira/browse/JSPF-65
Project: jSPF
Issue Type: Bug
Components: Core
Affects Versions: 0.9.6
Reporter: Stefano Bagnara
Priority: Critical
Fix For: 0.9.7
Today I found an hudson build hang on jspf tests.
It was good enough I have been able to take a stack dump of the build process.
I'm not sure if the problem is in jSPF or dnsjnio, but here is the stack.. I
have to investigate on this.
I ran jSPF tests hundreds of times and never seen this. Hudson built jspf 18
times, stuck only once.. let's hope this will show up more often.
Full thread dump Java HotSpot(TM) Server VM (1.5.0_14-b03 mixed mode):
"Thread-12" prio=10 tid=0x084f7278 nid=0x2b runnable [0xb2d40000..0xb2d40cb8]
at java.io.FileInputStream.readBytes(Native Method)
at java.io.FileInputStream.read(FileInputStream.java:194)
at
java.lang.UNIXProcess$DeferredCloseInputStream.read(UNIXProcess.java:227)
at sun.nio.cs.StreamDecoder$CharsetSD.readBytes(StreamDecoder.java:411)
at sun.nio.cs.StreamDecoder$CharsetSD.implRead(StreamDecoder.java:453)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:183)
- locked <0xf4eff148> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read(InputStreamReader.java:167)
at java.io.BufferedReader.fill(BufferedReader.java:136)
at java.io.BufferedReader.readLine(BufferedReader.java:299)
- locked <0xf4eff148> (a java.io.InputStreamReader)
at java.io.BufferedReader.readLine(BufferedReader.java:362)
at
org.apache.maven.surefire.booter.shade.org.codehaus.plexus.util.cli.StreamPumper.run(StreamPumper.java:153)
"Thread-11" prio=10 tid=0x09688cb0 nid=0x2a runnable [0xb2d81000..0xb2d81c38]
at java.io.FileInputStream.readBytes(Native Method)
at java.io.FileInputStream.read(FileInputStream.java:194)
at
java.lang.UNIXProcess$DeferredCloseInputStream.read(UNIXProcess.java:227)
at java.io.BufferedInputStream.read1(BufferedInputStream.java:254)
at java.io.BufferedInputStream.read(BufferedInputStream.java:313)
- locked <0xf4efa160> (a java.io.BufferedInputStream)
at sun.nio.cs.StreamDecoder$CharsetSD.readBytes(StreamDecoder.java:411)
at sun.nio.cs.StreamDecoder$CharsetSD.implRead(StreamDecoder.java:453)
at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:183)
- locked <0xf4efc608> (a java.io.InputStreamReader)
at java.io.InputStreamReader.read(InputStreamReader.java:167)
at java.io.BufferedReader.fill(BufferedReader.java:136)
at java.io.BufferedReader.readLine(BufferedReader.java:299)
- locked <0xf4efc608> (a java.io.InputStreamReader)
at java.io.BufferedReader.readLine(BufferedReader.java:362)
at
org.apache.maven.surefire.booter.shade.org.codehaus.plexus.util.cli.StreamPumper.run(StreamPumper.java:153)
"process reaper" daemon prio=10 tid=0x08478528 nid=0x29 runnable
[0xb37ae000..0xb37aeb38]
at java.lang.UNIXProcess.waitForProcessExit(Native Method)
at java.lang.UNIXProcess.access$900(UNIXProcess.java:17)
at java.lang.UNIXProcess$2$1.run(UNIXProcess.java:86)
"pool-1-thread-1" prio=10 tid=0x086f9c68 nid=0xe in Object.wait()
[0xb39fd000..0xb39feab8]
at java.lang.Object.wait(Native Method)
- waiting on <0xf4ef7ec8> (a java.lang.UNIXProcess)
at java.lang.Object.wait(Object.java:474)
at java.lang.UNIXProcess.waitFor(UNIXProcess.java:115)
- locked <0xf4ef7ec8> (a java.lang.UNIXProcess)
at
org.apache.maven.surefire.booter.shade.org.codehaus.plexus.util.cli.CommandLineUtils.executeCommandLine(CommandLineUtils.java:143)
at
org.apache.maven.surefire.booter.shade.org.codehaus.plexus.util.cli.CommandLineUtils.executeCommandLine(CommandLineUtils.java:95)
at
org.apache.maven.surefire.booter.SurefireBooter.fork(SurefireBooter.java:662)
at
org.apache.maven.surefire.booter.SurefireBooter.forkSuites(SurefireBooter.java:468)
at
org.apache.maven.surefire.booter.SurefireBooter.runSuitesForkOnce(SurefireBooter.java:368)
at
org.apache.maven.surefire.booter.SurefireBooter.run(SurefireBooter.java:241)
at
org.apache.maven.plugin.surefire.SurefirePlugin.execute(SurefirePlugin.java:481)
at
org.apache.maven.plugin.DefaultPluginManager.executeMojo(DefaultPluginManager.java:447)
at
hudson.maven.agent.PluginManagerInterceptor.executeMojo(PluginManagerInterceptor.java:136)
at
org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoals(DefaultLifecycleExecutor.java:539)
at
org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoalWithLifecycle(DefaultLifecycleExecutor.java:480)
at
org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoal(DefaultLifecycleExecutor.java:459)
at
org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeGoalAndHandleFailures(DefaultLifecycleExecutor.java:311)
at
org.apache.maven.lifecycle.DefaultLifecycleExecutor.executeTaskSegments(DefaultLifecycleExecutor.java:278)
at
org.apache.maven.lifecycle.DefaultLifecycleExecutor.execute(DefaultLifecycleExecutor.java:143)
at
org.apache.maven.lifecycle.LifecycleExecutorInterceptor.execute(LifecycleExecutorInterceptor.java:42)
at org.apache.maven.DefaultMaven.doExecute(DefaultMaven.java:333)
at org.apache.maven.DefaultMaven.execute(DefaultMaven.java:126)
at org.apache.maven.cli.MavenCli.main(MavenCli.java:282)
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:585)
at org.codehaus.classworlds.Launcher.launchEnhanced(Launcher.java:315)
at org.codehaus.classworlds.Launcher.launch(Launcher.java:255)
at hudson.maven.agent.Main.launch(Main.java:133)
at hudson.maven.MavenBuilder.call(MavenBuilder.java:129)
at
hudson.maven.MavenModuleSetBuild$Builder.call(MavenModuleSetBuild.java:528)
at
hudson.maven.MavenModuleSetBuild$Builder.call(MavenModuleSetBuild.java:474)
at hudson.remoting.UserRequest.perform(UserRequest.java:69)
at hudson.remoting.UserRequest.perform(UserRequest.java:23)
at hudson.remoting.Request$2.run(Request.java:206)
at
java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:417)
at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:269)
at java.util.concurrent.FutureTask.run(FutureTask.java:123)
at
java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675)
at java.lang.Thread.run(Thread.java:595)
"Channel reader thread: channel" prio=10 tid=0x0854e480 nid=0xd runnable
[0xb3c9e000..0xb3c9ed38]
at java.net.SocketInputStream.socketRead0(Native Method)
at java.net.SocketInputStream.read(SocketInputStream.java:129)
at java.net.SocketInputStream.read(SocketInputStream.java:182)
at java.io.FilterInputStream.read(FilterInputStream.java:66)
at
java.io.ObjectInputStream$PeekInputStream.peek(ObjectInputStream.java:2196)
at
java.io.ObjectInputStream$BlockDataInputStream.peek(ObjectInputStream.java:2486)
at
java.io.ObjectInputStream$BlockDataInputStream.peekByte(ObjectInputStream.java:2496)
at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1273)
at java.io.ObjectInputStream.readObject(ObjectInputStream.java:348)
at hudson.remoting.Channel$ReaderThread.run(Channel.java:576)
"Low Memory Detector" daemon prio=10 tid=0x08192100 nid=0xb runnable
[0x00000000..0x00000000]
"CompilerThread1" daemon prio=10 tid=0x08190868 nid=0xa waiting on condition
[0x00000000..0xf8078048]
"CompilerThread0" daemon prio=10 tid=0x0818fa38 nid=0x9 waiting on condition
[0x00000000..0xf80b8ec8]
"AdapterThread" daemon prio=10 tid=0x0818ebe0 nid=0x8 waiting on condition
[0x00000000..0x00000000]
"Signal Dispatcher" daemon prio=10 tid=0x0818de18 nid=0x7 waiting on condition
[0x00000000..0x00000000]
"Finalizer" daemon prio=10 tid=0x08181880 nid=0x6 in Object.wait()
[0xf817c000..0xf817cab8]
at java.lang.Object.wait(Native Method)
- waiting on <0xb7ecc378> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120)
- locked <0xb7ecc378> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:136)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
"Reference Handler" daemon prio=10 tid=0x08181380 nid=0x5 in Object.wait()
[0xf81bd000..0xf81bdd38]
at java.lang.Object.wait(Native Method)
- waiting on <0xb8057e80> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:474)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0xb8057e80> (a java.lang.ref.Reference$Lock)
"main" prio=10 tid=0x080748f8 nid=0x1 in Object.wait() [0x08046000..0x08046d78]
at java.lang.Object.wait(Native Method)
- waiting on <0xb80ad328> (a hudson.remoting.Channel)
at java.lang.Object.wait(Object.java:474)
at hudson.remoting.Channel.join(Channel.java:479)
- locked <0xb80ad328> (a hudson.remoting.Channel)
at hudson.remoting.Launcher.main(Launcher.java:99)
at hudson.remoting.Launcher.main(Launcher.java:82)
at hudson.remoting.Launcher.main(Launcher.java:78)
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:585)
at hudson.maven.agent.Main.main(Main.java:91)
at hudson.maven.agent.Main.main(Main.java:38)
"VM Thread" prio=10 tid=0x0817f2a8 nid=0x4 runnable
"GC task thread#0 (ParallelGC)" prio=10 tid=0x080f6678 nid=0x2 runnable
"GC task thread#1 (ParallelGC)" prio=10 tid=0x080f70b8 nid=0x3 runnable
"VM Periodic Task Thread" prio=10 tid=0x080edd70 nid=0xc waiting on condition
Full thread dump Java HotSpot(TM) Server VM (1.5.0_14-b03 mixed mode):
"DnsSelect" daemon prio=10 tid=0x08388b70 nid=0x14 runnable
[0xb36be000..0xb36bed38]
at sun.nio.ch.DevPollArrayWrapper.poll0(Native Method)
at sun.nio.ch.DevPollArrayWrapper.poll(DevPollArrayWrapper.java:164)
at sun.nio.ch.DevPollSelectorImpl.doSelect(DevPollSelectorImpl.java:68)
at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
- locked <0xf3494f30> (a sun.nio.ch.Util$1)
- locked <0xf3494f20> (a java.util.Collections$UnmodifiableSet)
- locked <0xf3494cf8> (a sun.nio.ch.DevPollSelectorImpl)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:84)
at uk.nominet.dnsjnio.DnsController.selectLoop(Unknown Source)
at uk.nominet.dnsjnio.DnsController.access$000(Unknown Source)
at uk.nominet.dnsjnio.DnsController$1.run(Unknown Source)
"DnsTimer" daemon prio=10 tid=0x08362d88 nid=0x13 waiting on condition
[0xb3738000..0xb3738cb8]
at java.lang.Thread.sleep(Native Method)
at uk.nominet.dnsjnio.Timer$1.run(Unknown Source)
"LookupAsynchResolver" prio=10 tid=0x08372c38 nid=0x12 in Object.wait()
[0xb3779000..0xb3779c38]
at java.lang.Object.wait(Native Method)
- waiting on <0xf3496578> (a uk.nominet.dnsjnio.ResponseQueue)
at java.lang.Object.wait(Object.java:474)
at uk.nominet.dnsjnio.ResponseQueue.getItem(Unknown Source)
- locked <0xf3496578> (a uk.nominet.dnsjnio.ResponseQueue)
at org.xbill.DNS.LookupAsynch$ProcessingTask.run(Unknown Source)
- locked <0xf3496578> (a uk.nominet.dnsjnio.ResponseQueue)
at java.lang.Thread.run(Thread.java:595)
"SPFExecutor" daemon prio=10 tid=0x0855bba0 nid=0x11 in Object.wait()
[0xb37ba000..0xb37babb8]
at java.lang.Object.wait(Native Method)
- waiting on <0xf3495d18> (a
org.apache.james.jspf.executor.StagedMultipleSPFExecutor$ResponseQueueImpl)
at java.lang.Object.wait(Object.java:474)
at
org.apache.james.jspf.executor.StagedMultipleSPFExecutor$ResponseQueueImpl.removeResponse(StagedMultipleSPFExecutor.java:64)
- locked <0xf3495d18> (a
org.apache.james.jspf.executor.StagedMultipleSPFExecutor$ResponseQueueImpl)
at
org.apache.james.jspf.executor.StagedMultipleSPFExecutor.run(StagedMultipleSPFExecutor.java:175)
at java.lang.Thread.run(Thread.java:595)
"EnbrResolutionThread" prio=10 tid=0x0855b6f0 nid=0x10 in Object.wait()
[0xb37fb000..0xb37fbb38]
at java.lang.Object.wait(Native Method)
- waiting on <0xf3495948> (a uk.nominet.dnsjnio.ResponseQueue)
at java.lang.Object.wait(Object.java:474)
at uk.nominet.dnsjnio.ResponseQueue.getItem(Unknown Source)
- locked <0xf3495948> (a uk.nominet.dnsjnio.ResponseQueue)
at
org.xbill.DNS.ExtendedNonblockingResolver$ResolutionThread.run(Unknown Source)
"EnbrResolutionThread" prio=10 tid=0x08462f60 nid=0xf in Object.wait()
[0xb383c000..0xb383cab8]
at java.lang.Object.wait(Native Method)
- waiting on <0xf3496520> (a uk.nominet.dnsjnio.ResponseQueue)
at java.lang.Object.wait(Object.java:474)
at uk.nominet.dnsjnio.ResponseQueue.getItem(Unknown Source)
- locked <0xf3496520> (a uk.nominet.dnsjnio.ResponseQueue)
at
org.xbill.DNS.ExtendedNonblockingResolver$ResolutionThread.run(Unknown Source)
"Thread-1" daemon prio=10 tid=0x084627d0 nid=0xe runnable
[0xb387d000..0xb387da38]
at java.net.PlainDatagramSocketImpl.receive0(Native Method)
- locked <0xf3497480> (a java.net.PlainDatagramSocketImpl)
at
java.net.PlainDatagramSocketImpl.receive(PlainDatagramSocketImpl.java:136)
- locked <0xf3497480> (a java.net.PlainDatagramSocketImpl)
at java.net.DatagramSocket.receive(DatagramSocket.java:712)
- locked <0xf34974c0> (a java.net.DatagramPacket)
- locked <0xf34974e0> (a java.net.DatagramSocket)
at org.apache.james.jspf.dnsserver.UDPListener.run(UDPListener.java:130)
at java.lang.Thread.run(Thread.java:595)
"Thread-0" daemon prio=10 tid=0x083ec700 nid=0xd runnable
[0xb38be000..0xb38bedb8]
at java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
- locked <0xf3497530> (a java.net.SocksSocketImpl)
at java.net.ServerSocket.implAccept(ServerSocket.java:450)
at java.net.ServerSocket.accept(ServerSocket.java:421)
at org.apache.james.jspf.dnsserver.TCPListener.run(TCPListener.java:128)
at java.lang.Thread.run(Thread.java:595)
"Low Memory Detector" daemon prio=10 tid=0x08191d58 nid=0xb runnable
[0x00000000..0x00000000]
"CompilerThread1" daemon prio=10 tid=0x081904e0 nid=0xa waiting on condition
[0x00000000..0xf8077fc0]
"CompilerThread0" daemon prio=10 tid=0x0818f6b0 nid=0x9 waiting on condition
[0x00000000..0xf80b8f48]
"AdapterThread" daemon prio=10 tid=0x0818e880 nid=0x8 waiting on condition
[0x00000000..0x00000000]
"Signal Dispatcher" daemon prio=10 tid=0x0818dab8 nid=0x7 waiting on condition
[0x00000000..0x00000000]
"Finalizer" daemon prio=10 tid=0x08182530 nid=0x6 in Object.wait()
[0xf817c000..0xf817ca38]
at java.lang.Object.wait(Native Method)
- waiting on <0xf3497978> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120)
- locked <0xf3497978> (a java.lang.ref.ReferenceQueue$Lock)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:136)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
"Reference Handler" daemon prio=10 tid=0x08181030 nid=0x5 in Object.wait()
[0xf81bd000..0xf81bddb8]
at java.lang.Object.wait(Native Method)
- waiting on <0xf34841a8> (a java.lang.ref.Reference$Lock)
at java.lang.Object.wait(Object.java:474)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
- locked <0xf34841a8> (a java.lang.ref.Reference$Lock)
"main" prio=10 tid=0x080745c0 nid=0x1 in Object.wait() [0x08046000..0x08046eb0]
at java.lang.Object.wait(Native Method)
- waiting on <0xf3496270> (a
org.apache.james.jspf.executor.FutureSPFResult)
at java.lang.Object.wait(Object.java:474)
at
org.apache.james.jspf.executor.FutureSPFResult.checkReady(FutureSPFResult.java:56)
- locked <0xf3496270> (a org.apache.james.jspf.executor.FutureSPFResult)
at
org.apache.james.jspf.executor.FutureSPFResult.getResult(FutureSPFResult.java:99)
at
org.apache.james.jspf.AbstractYamlTest.verifyResult(AbstractYamlTest.java:296)
at
org.apache.james.jspf.AbstractYamlTest.runTest(AbstractYamlTest.java:264)
at junit.framework.TestCase.runBare(TestCase.java:127)
at junit.framework.TestResult$1.protect(TestResult.java:106)
at junit.framework.TestResult.runProtected(TestResult.java:124)
at junit.framework.TestResult.run(TestResult.java:109)
at junit.framework.TestCase.run(TestCase.java:118)
at junit.framework.TestSuite.runTest(TestSuite.java:208)
at junit.framework.TestSuite.run(TestSuite.java:203)
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:585)
at
org.apache.maven.surefire.junit.JUnitTestSet.execute(JUnitTestSet.java:213)
at
org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.executeTestSet(AbstractDirectoryTestSuite.java:140)
at
org.apache.maven.surefire.suite.AbstractDirectoryTestSuite.execute(AbstractDirectoryTestSuite.java:127)
at org.apache.maven.surefire.Surefire.run(Surefire.java:177)
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:585)
at
org.apache.maven.surefire.booter.SurefireBooter.runSuitesInProcess(SurefireBooter.java:334)
at
org.apache.maven.surefire.booter.SurefireBooter.main(SurefireBooter.java:980)
"VM Thread" prio=10 tid=0x0817ef58 nid=0x4 runnable
"GC task thread#0 (ParallelGC)" prio=10 tid=0x080f6318 nid=0x2 runnable
"GC task thread#1 (ParallelGC)" prio=10 tid=0x080f6d58 nid=0x3 runnable
"VM Periodic Task Thread" prio=10 tid=0x080eda10 nid=0xc waiting on condition
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
---------------------------------------------------------------------
To unsubscribe, e-mail: [EMAIL PROTECTED]
For additional commands, e-mail: [EMAIL PROTECTED]
