I think the reflection and PowerMock warnings here are probably a red herring. We pulled down the artifacts and found that the DUnit job is hanging due to stuck threads in a newer DUnit test. I am not sure why it isn't failing the test but rather failing the entire job. I believe Bruce Schuchart is going to dig into this a bit. Analysis from Lynn Hughes-Godfrey:
So, I downloaded https://concourse.apachegeode-ci.info/teams/main/pipelines/apache-develop-main/jobs/DistributedTestOpenJDK8/builds/961 to /Users/lhughesgodfrey/Downloads/distributedtestfiles-OpenJDK8-1.11.0-SNAPSHOT.0010/geode-core/build/distributedTest In that callstacks directory, you'll see dunit-hangs.txt ... and this test has been running for over an hour ... ``` Started @ 2019-08-07 07:54:10.272 +0000 2019-08-07 08:22:25.440 +0000 org.apache.geode.cache30.DistributedMulticastRegionDUnitTest testMulticastAfterReconnect Ended @ 2019-08-07 08:58:50.243 +0000 ``` When I look at the callstacks (at the top level), I see this: ``` "Pooled Waiting Message Processor 1" #213 daemon prio=5 os_prio=0 tid=0x00007fc738024000 nid=0x488 waiting for monitor entry [0x00007fc7ec5f7000] java.lang.Thread.State: BLOCKED (on object monitor) at org.apache.geode.distributed.internal.membership.adapter.GMSMembershipManager.startEventProcessing(GMSMembershipManager.java:1179) - waiting to lock <0x00000000e03a75e0> (a java.lang.Object) at org.apache.geode.distributed.internal.ClusterDistributionManager.readyForMessages(ClusterDistributionManager.java:1152) at org.apache.geode.distributed.internal.ClusterDistributionManager.lambda$startThreads$10(ClusterDistributionManager.java:1129) at org.apache.geode.distributed.internal.ClusterDistributionManager$$Lambda$87/1408912936.run(Unknown Source) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at org.apache.geode.distributed.internal.ClusterDistributionManager.runUntilShutdown(ClusterDistributionManager.java:961) at org.apache.geode.distributed.internal.ClusterDistributionManager.doWaitingThread(ClusterDistributionManager.java:851) at org.apache.geode.distributed.internal.ClusterDistributionManager$$Lambda$53/274751999.invoke(Unknown Source) at org.apache.geode.internal.logging.LoggingThreadFactory.lambda$newThread$0(LoggingThreadFactory.java:121) at org.apache.geode.internal.logging.LoggingThreadFactory$$Lambda$49/1824093464.run(Unknown Source) at java.lang.Thread.run(Thread.java:748) Locked ownable synchronizers: - <0x00000000e03a7660> (a java.util.concurrent.ThreadPoolExecutor$Worker) ``` This thread holds the lock: ``` "ReconnectThread" #193 prio=5 os_prio=0 tid=0x00007fc7cc219000 nid=0x46a waiting on condition [0x00007fc78bdfb000] java.lang.Thread.State: TIMED_WAITING (sleeping) at java.lang.Thread.sleep(Native Method) at org.apache.geode.internal.tcp.Connection.createSender(Connection.java:959) at org.apache.geode.internal.tcp.ConnectionTable.handleNewPendingConnection(ConnectionTable.java:297) at org.apache.geode.internal.tcp.ConnectionTable.getSharedConnection(ConnectionTable.java:408) at org.apache.geode.internal.tcp.ConnectionTable.get(ConnectionTable.java:593) at org.apache.geode.internal.tcp.TCPConduit.getConnection(TCPConduit.java:825) at org.apache.geode.distributed.internal.direct.DirectChannel.getConnections(DirectChannel.java:537) at org.apache.geode.distributed.internal.direct.DirectChannel.sendToMany(DirectChannel.java:326) at org.apache.geode.distributed.internal.direct.DirectChannel.sendToOne(DirectChannel.java:241) at org.apache.geode.distributed.internal.direct.DirectChannel.send(DirectChannel.java:596) at org.apache.geode.distributed.internal.membership.adapter.GMSMembershipManager.directChannelSend(GMSMembershipManager.java:1558) at org.apache.geode.distributed.internal.membership.adapter.GMSMembershipManager.send(GMSMembershipManager.java:1739) at org.apache.geode.distributed.internal.ClusterDistributionManager.sendViaMembershipManager(ClusterDistributionManager.java:2849) at org.apache.geode.distributed.internal.ClusterDistributionManager.sendOutgoing(ClusterDistributionManager.java:2776) at org.apache.geode.distributed.internal.ClusterDistributionManager.sendMessage(ClusterDistributionManager.java:2813) at org.apache.geode.distributed.internal.ClusterDistributionManager.putOutgoing(ClusterDistributionManager.java:1523) at org.apache.geode.distributed.internal.ReplyMessage.send(ReplyMessage.java:174) at org.apache.geode.internal.cache.DistributedCacheOperation$CacheOperationMessage.sendReply(DistributedCacheOperation.java:1269) at org.apache.geode.internal.cache.DistributedCacheOperation$CacheOperationMessage.process(DistributedCacheOperation.java:1132) at org.apache.geode.distributed.internal.DistributionMessage.scheduleAction(DistributionMessage.java:370) at org.apache.geode.distributed.internal.DistributionMessage.schedule(DistributionMessage.java:425) at org.apache.geode.distributed.internal.ClusterDistributionManager.scheduleIncomingMessage(ClusterDistributionManager.java:2862) at org.apache.geode.distributed.internal.ClusterDistributionManager.handleIncomingDMsg(ClusterDistributionManager.java:2549) at org.apache.geode.distributed.internal.ClusterDistributionManager.access$1700(ClusterDistributionManager.java:113) at org.apache.geode.distributed.internal.ClusterDistributionManager$DMListener.messageReceived(ClusterDistributionManager.java:3388) at org.apache.geode.distributed.internal.membership.adapter.GMSMembershipManager.dispatchMessage(GMSMembershipManager.java:1043) at org.apache.geode.distributed.internal.membership.adapter.GMSMembershipManager.processStartupEvent(GMSMembershipManager.java:1154) at org.apache.geode.distributed.internal.membership.adapter.GMSMembershipManager.startEventProcessing(GMSMembershipManager.java:1205) - locked <0x00000000e03a75e0> (a java.lang.Object) at org.apache.geode.distributed.internal.ClusterDistributionManager.<init>(ClusterDistributionManager.java:911) at org.apache.geode.distributed.internal.ClusterDistributionManager.create(ClusterDistributionManager.java:540) at org.apache.geode.distributed.internal.InternalDistributedSystem.initialize(InternalDistributedSystem.java:756) at org.apache.geode.distributed.internal.InternalDistributedSystem.access$200(InternalDistributedSystem.java:135) at org.apache.geode.distributed.internal.InternalDistributedSystem$Builder.build(InternalDistributedSystem.java:2994) at org.apache.geode.distributed.internal.InternalDistributedSystem.connectInternal(InternalDistributedSystem.java:251) - locked <0x00000000e0397568> (a java.lang.Object) at org.apache.geode.distributed.DistributedSystem.connect(DistributedSystem.java:158) at org.apache.geode.distributed.internal.InternalDistributedSystem.reconnect(InternalDistributedSystem.java:2575) at org.apache.geode.distributed.internal.InternalDistributedSystem.tryReconnect(InternalDistributedSystem.java:2392) - locked <0x00000000e045f178> (a java.lang.Object) - locked <0x00000000e047a880> (a java.lang.Class for org.apache.geode.internal.cache.GemFireCacheImpl) - locked <0x00000000e0512eb8> (a java.lang.Class for org.apache.geode.internal.cache.InternalCacheBuilder) at org.apache.geode.distributed.internal.InternalDistributedSystem.disconnect(InternalDistributedSystem.java:1207) at org.apache.geode.distributed.internal.ClusterDistributionManager$DMListener.membershipFailure(ClusterDistributionManager.java:3383) at org.apache.geode.distributed.internal.membership.adapter.GMSMembershipManager.uncleanShutdown(GMSMembershipManager.java:1441) at org.apache.geode.distributed.internal.membership.adapter.GMSMembershipManager$ManagerImpl.lambda$forceDisconnect$0(GMSMembershipManager.java:2613) at org.apache.geode.distributed.internal.membership.adapter.GMSMembershipManager$ManagerImpl$$Lambda$198/1187156898.run(Unknown Source) at java.lang.Thread.run(Thread.java:748) Locked ownable synchronizers: - None ``` Another blocked thread: ``` "RMI TCP Connection(1)-172.17.0.13" #32 daemon prio=5 os_prio=0 tid=0x00007fc7d4001800 nid=0x27e waiting for monitor entry [0x00007fc849054000] java.lang.Thread.State: BLOCKED (on object monitor) at java.lang.Object.wait(Native Method) - waiting on <0x00000000e045f178> (a java.lang.Object) at org.apache.geode.distributed.internal.InternalDistributedSystem.waitUntilReconnected(InternalDistributedSystem.java:2895) - locked <0x00000000e045f178> (a java.lang.Object) at org.apache.geode.internal.cache.GemFireCacheImpl.waitUntilReconnected(GemFireCacheImpl.java:2408) at org.apache.geode.cache30.DistributedMulticastRegionDUnitTest.lambda$testMulticastAfterReconnect$bb17a952$1(DistributedMulticastRegionDUnitTest.java:168) at org.apache.geode.cache30.DistributedMulticastRegionDUnitTest$$Lambda$200/626559185.run(Unknown Source) at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method) at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at org.apache.geode.test.dunit.internal.MethodInvoker.executeObject(MethodInvoker.java:123) at org.apache.geode.test.dunit.internal.RemoteDUnitVM.executeMethodOnObject(RemoteDUnitVM.java:69) at sun.reflect.GeneratedMethodAccessor6.invoke(Unknown Source) at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at java.lang.reflect.Method.invoke(Method.java:498) at sun.rmi.server.UnicastServerRef.dispatch(UnicastServerRef.java:357) at sun.rmi.transport.Transport$1.run(Transport.java:200) at sun.rmi.transport.Transport$1.run(Transport.java:197) at java.security.AccessController.doPrivileged(Native Method) at sun.rmi.transport.Transport.serviceCall(Transport.java:196) at sun.rmi.transport.tcp.TCPTransport.handleMessages(TCPTransport.java:573) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run0(TCPTransport.java:834) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.lambda$run$0(TCPTransport.java:688) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler$$Lambda$8/1801094145.run(Unknown Source) at java.security.AccessController.doPrivileged(Native Method) at sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run(TCPTransport.java:687) 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) Locked ownable synchronizers: - <0x00000000e01b9da0> (a java.util.concurrent.ThreadPoolExecutor$Worker) ``` Thanks, Ryan On Wed, Aug 7, 2019 at 10:05 AM Kirk Lund <kl...@apache.org> wrote: > We previously decided to stop using PowerMock in any Geode tests and remove > it. Ryan and I created https://issues.apache.org/jira/browse/GEODE-6143 > but > it's languishing because it takes a lot of time to strip out PowerMock from > a test. > > I don't get any PowerMock warnings locally when I run unit tests. > > On Wed, Aug 7, 2019 at 9:50 AM Murtuza Boxwala <mboxw...@pivotal.io> > wrote: > > > Yea. I think it might be a red herring, because I am seeing those errors > > in every run, passing ones two…just double checked on > > > https://concourse.apachegeode-ci.info/teams/main/pipelines/apache-develop-main/jobs/UnitTestOpenJDK11/builds/948 > > < > > > https://concourse.apachegeode-ci.info/teams/main/pipelines/apache-develop-main/jobs/UnitTestOpenJDK11/builds/948 > > > > > > > If we don’t have any other ideas, though, it might be worth removing > them. > > > > It is odd that you don’t see them locally. Let me see if I can get them > to > > show up…it might have something to do with the logging level. > > > > > On Aug 7, 2019, at 12:45 PM, Kirk Lund <kl...@apache.org> wrote: > > > > > > I don't know if the PowerMock warnings are related but that's the only > > > thing interesting in the output before "timeout exceeded". > > > > > > On Wed, Aug 7, 2019 at 9:43 AM Murtuza Boxwala <mboxw...@pivotal.io> > > wrote: > > > > > >> How down know these warnings are related to the builds hanging. When > I > > >> was on CIO duty a couple days ago, I remember seeing this warning in a > > >> failing build, but then I looked back at passing builds on saw this as > > well. > > >> > > >>> On Aug 7, 2019, at 12:40 PM, Kirk Lund <kl...@apache.org> wrote: > > >>> > > >>> The build is broken in CI right now (for main CI and PRs). The > UnitTest > > >>> jobs are timing out so I assume there's a hang of some sort. > > >>> > > >>> The WARNINGs appear to be related to PowerMock and begins with "An > > >> illegal > > >>> reflective access operation" in geode-assembly:test. > > >>> > > >>> I'm running unit tests locally and haven't hit this yet, but maybe we > > >>> should consider disabling all PowerMock tests and increase priority > on > > >>> re-enabling them without PowerMock? > > >>> > > >>>> Task :geode-assembly:test > > >>> WARNING: An illegal reflective access operation has occurred > > >>> WARNING: Illegal reflective access by > > >>> org.mockito.internal.util.reflection.AccessibilityChanger > > >>> > > >> > > > (file:/home/geode/.gradle/caches/modules-2/files-2.1/org.mockito/mockito-core/2.23.0/497ddb32fd5d01f9dbe99a2ec790aeb931dff1b1/mockito-core-2.23.0.jar) > > >>> to field java.io.File.path > > >>> WARNING: Please consider reporting this to the maintainers of > > >>> org.mockito.internal.util.reflection.AccessibilityChanger > > >>> WARNING: Use --illegal-access=warn to enable warnings of further > > illegal > > >>> reflective access operations > > >>> WARNING: All illegal access operations will be denied in a future > > release > > >>> WARNING: An illegal reflective access operation has occurred > > >>> WARNING: Illegal reflective access by > > >>> org.mockito.internal.util.reflection.AccessibilityChanger > > >>> > > >> > > > (file:/home/geode/.gradle/caches/modules-2/files-2.1/org.mockito/mockito-core/2.23.0/497ddb32fd5d01f9dbe99a2ec790aeb931dff1b1/mockito-core-2.23.0.jar) > > >>> to field java.io.File.path > > >>> WARNING: Please consider reporting this to the maintainers of > > >>> org.mockito.internal.util.reflection.AccessibilityChanger > > >>> WARNING: Use --illegal-access=warn to enable warnings of further > > illegal > > >>> reflective access operations > > >>> WARNING: All illegal access operations will be denied in a future > > release > > >>> > > >>>> Task :geode-core:test > > >>> WARNING: An illegal reflective access operation has occurred > > >>> WARNING: Illegal reflective access by > > >>> org.apache.geode.distributed.internal.deadlock.UnsafeThreadLocal > > >>> (file:/home/geode/geode/geode-core/build/classes/java/main/) to > method > > >>> java.lang.ThreadLocal.getMap(java.lang.Thread) > > >>> WARNING: Please consider reporting this to the maintainers of > > >>> org.apache.geode.distributed.internal.deadlock.UnsafeThreadLocal > > >>> WARNING: Use --illegal-access=warn to enable warnings of further > > illegal > > >>> reflective access operations > > >>> WARNING: All illegal access operations will be denied in a future > > release > > >>> WARNING: An illegal reflective access operation has occurred > > >>> WARNING: Illegal reflective access by > > >>> org.mockito.internal.util.reflection.AccessibilityChanger > > >>> > > >> > > > (file:/home/geode/.gradle/caches/modules-2/files-2.1/org.mockito/mockito-core/2.23.0/497ddb32fd5d01f9dbe99a2ec790aeb931dff1b1/mockito-core-2.23.0.jar) > > >>> to field java.util.Date.fastTime > > >>> WARNING: Please consider reporting this to the maintainers of > > >>> org.mockito.internal.util.reflection.AccessibilityChanger > > >>> WARNING: Use --illegal-access=warn to enable warnings of further > > illegal > > >>> reflective access operations > > >>> WARNING: All illegal access operations will be denied in a future > > release > > >>> WARNING: An illegal reflective access operation has occurred > > >>> WARNING: Illegal reflective access by > > >>> org.powermock.reflect.internal.WhiteboxImpl > > >>> > > >> > > > (file:/home/geode/.gradle/caches/modules-2/files-2.1/org.powermock/powermock-reflect/2.0.0-beta.5/4ea415348f15620783a1f26343d6732adfa86bc8/powermock-reflect-2.0.0-beta.5.jar) > > >>> to method java.lang.Object.finalize() > > >>> WARNING: Please consider reporting this to the maintainers of > > >>> org.powermock.reflect.internal.WhiteboxImpl > > >>> WARNING: Use --illegal-access=warn to enable warnings of further > > illegal > > >>> reflective access operations > > >>> WARNING: All illegal access operations will be denied in a future > > release > > >>> WARNING: An illegal reflective access operation has occurred > > >>> WARNING: Illegal reflective access by > > >>> org.junit.contrib.java.lang.system.EnvironmentVariables > > >>> > > >> > > > (file:/home/geode/.gradle/caches/modules-2/files-2.1/com.github.stefanbirkner/system-rules/1.19.0/d541c9a1cff0dda32e2436c74562e2e4aa6c88cd/system-rules-1.19.0.jar) > > >>> to field java.util.Collections$UnmodifiableMap.m > > >>> WARNING: Please consider reporting this to the maintainers of > > >>> org.junit.contrib.java.lang.system.EnvironmentVariables > > >>> WARNING: Use --illegal-access=warn to enable warnings of further > > illegal > > >>> reflective access operations > > >>> WARNING: All illegal access operations will be denied in a future > > release > > >>> > > >>> timeout exceeded > > >> > > >> > > > > >
