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
