[
https://issues.apache.org/jira/browse/GEODE-1769?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15419464#comment-15419464
]
Hitesh Khamesra commented on GEODE-1769:
----------------------------------------
Class
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest
all > com.gemstone.gemfire.security >
IntegratedClientRegisterInterestAuthDistributedTest
3
tests
1
failures
0
ignored
0.459s
duration
66%
successful
Failed tests
Tests
Standard output
Standard error
Failed tests
testRegisterInterest
java.lang.AssertionError: Suspicious strings were written to the log during
this run.
Fix the strings or use IgnoredException.addIgnoredException to ignore.
-----------------------------------------------------------------------
Found suspect string in log4j at line 91
[fatal 2016/08/11 15:55:58.089 PDT <JMX client heartbeat 2> tid=0xae] (tid=174
msgId=10) No longer connected to localhost[20406].
at org.junit.Assert.fail(Assert.java:88)
at
com.gemstone.gemfire.test.dunit.standalone.DUnitLauncher.closeAndCheckForSuspects(DUnitLauncher.java:358)
at
com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase.cleanupAllVms(JUnit4DistributedTestCase.java:542)
at
com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase.tearDownDistributedTestCase(JUnit4DistributedTestCase.java:491)
at
com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase.tearDown(JUnit4DistributedTestCase.java:480)
at sun.reflect.GeneratedMethodAccessor11.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at
org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:50)
at
org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
at
org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:47)
at
org.junit.internal.runners.statements.RunAfters.evaluate(RunAfters.java:33)
at org.junit.rules.TestWatcher$1.evaluate(TestWatcher.java:55)
at org.junit.rules.RunRules.evaluate(RunRules.java:20)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:325)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:78)
at
org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:57)
at org.junit.runners.ParentRunner$3.run(ParentRunner.java:290)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:71)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:288)
at org.junit.runners.ParentRunner.access$000(ParentRunner.java:58)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:268)
at
org.junit.internal.runners.statements.RunBefores.evaluate(RunBefores.java:26)
at org.junit.runners.ParentRunner.run(ParentRunner.java:363)
at
org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecuter.runTestClass(JUnitTestClassExecuter.java:114)
at
org.gradle.api.internal.tasks.testing.junit.JUnitTestClassExecuter.execute(JUnitTestClassExecuter.java:57)
at
org.gradle.api.internal.tasks.testing.junit.JUnitTestClassProcessor.processTestClass(JUnitTestClassProcessor.java:66)
at
org.gradle.api.internal.tasks.testing.SuiteTestClassProcessor.processTestClass(SuiteTestClassProcessor.java:51)
at sun.reflect.GeneratedMethodAccessor14.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at
org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
at
org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
at
org.gradle.internal.dispatch.ContextClassLoaderDispatch.dispatch(ContextClassLoaderDispatch.java:32)
at
org.gradle.internal.dispatch.ProxyDispatchAdapter$DispatchingInvocationHandler.invoke(ProxyDispatchAdapter.java:93)
at com.sun.proxy.$Proxy2.processTestClass(Unknown Source)
at
org.gradle.api.internal.tasks.testing.worker.TestWorker.processTestClass(TestWorker.java:109)
at sun.reflect.GeneratedMethodAccessor13.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:497)
at
org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:35)
at
org.gradle.internal.dispatch.ReflectionDispatch.dispatch(ReflectionDispatch.java:24)
at
org.gradle.internal.remote.internal.hub.MessageHub$Handler.run(MessageHub.java:377)
at
org.gradle.internal.concurrent.ExecutorPolicy$CatchAndRecordFailures.onExecute(ExecutorPolicy.java:54)
at
org.gradle.internal.concurrent.StoppableExecutorImpl$1.run(StoppableExecutorImpl.java:40)
at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at java.lang.Thread.run(Thread.java:745)
Tests
Test Duration Result
testRegisterInterest 0.159s failed
testRegisterInterestList 0.123s passed
testRegisterInterestRegex 0.177s passed
Standard output
Previously run tests: [PRDistTXDUnitTest, DistTXWithDeltaDUnitTest,
DistTXPersistentDebugDUnitTest, PersistentPartitionedRegionWithDistTXDUnitTest,
DistTXOrderDUnitTest, PRDistTXWithVersionsDUnitTest, CacheMapDistTXDUnitTest,
DistTXRestrictionsDUnitTest, DistributedTransactionDUnitTest,
DistTXDebugDUnitTest, IntegratedClientGetEntryAuthDistributedTest,
PDXGfshPostProcessorOnRemoteServerTest,
IntegratedClientGetPutAuthDistributedTest,
IntegratedClientRegisterInterestAuthDistributedTest]
[vm_1][info 2016/08/11 15:55:57.704 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(setupVM)
[vm_1][info 2016/08/11 15:55:57.704 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(setupVM) (took 0 ms)
[vm_2][info 2016/08/11 15:55:57.705 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(setupVM)
[vm_2][info 2016/08/11 15:55:57.705 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(setupVM) (took 0 ms)
[setup] START TEST
IntegratedClientRegisterInterestAuthDistributedTest.testRegisterInterestRegex
distributed system properties: {mcast-port=0, security-log-level=finest,
log-level=info, disable-auto-reconnect=true,
enable-cluster-configuration=false,
security-manager=org.apache.geode.security.templates.SampleSecurityManager,
security-pdx=false, locators=, use-cluster-configuration=false,
security-json=com/gemstone/gemfire/management/internal/security/clientServer.json}
[vm_3][info 2016/08/11 15:55:57.710 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(setupVM)
[vm_3][info 2016/08/11 15:55:57.710 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(setupVM) (took 0 ms)
[debug 2016/08/11 15:55:57.718 PDT <Test worker> tid=0xa] Changing level for
Logger 'com.gemstone.gemfire.security' from TRACE to TRACE
[debug 2016/08/11 15:55:57.718 PDT <Test worker> tid=0xa] skipping banner -
Locator.inhibitDMBanner is set to true
[debug 2016/08/11 15:55:57.718 PDT <Test worker> tid=0xa] SecurityLogWriter is
created.
[info 2016/08/11 15:55:57.725 PDT <Test worker> tid=0xa] Running in local mode
since no locators were specified.
[info 2016/08/11 15:55:57.729 PDT <Test worker> tid=0xa] Initializing region
_monitoringRegion_10.118.32.90<v-1>0
[info 2016/08/11 15:55:57.729 PDT <Test worker> tid=0xa] Initialization of
region _monitoringRegion_10.118.32.90<v-1>0 completed
[info 2016/08/11 15:55:57.733 PDT <Test worker> tid=0xa] Initializing region
AuthRegion
[info 2016/08/11 15:55:57.734 PDT <Test worker> tid=0xa] Initialization of
region AuthRegion completed
[info 2016/08/11 15:55:57.735 PDT <Test worker> tid=0xa] Updating membership
port. Port changed from 0 to 60,187. ID is now
venezuela(3448:loner):0:16bbd17b
[info 2016/08/11 15:55:57.735 PDT <Test worker> tid=0xa] Cache server
connection listener bound to address 0.0.0.0/0.0.0.0:60187 with backlog 1,000.
[info 2016/08/11 15:55:57.735 PDT <Test worker> tid=0xa]
ClientHealthMonitorThread maximum allowed time between pings: 60,000
[info 2016/08/11 15:55:57.736 PDT <Test worker> tid=0xa] CacheServer
Configuration: port=60187 max-connections=800 max-threads=0
notify-by-subscription=true socket-buffer-size=32768
maximum-time-between-pings=60000 maximum-message-count=230000
message-time-to-live=180 eviction-policy=none capacity=1 overflow directory=.
groups=[] loadProbe=ConnectionCountProbe loadPollInterval=5000 tcpNoDelay=true
[vm_3][info 2016/08/11 15:55:57.743 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$67/2093533096.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$67/2093533096@54031ed6
[vm_3][debug 2016/08/11 15:55:57.745 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Changing level for Logger 'com.gemstone.gemfire.security' from TRACE
to TRACE
[vm_3][debug 2016/08/11 15:55:57.745 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] skipping banner - Locator.inhibitDMBanner is set to true
[vm_3][debug 2016/08/11 15:55:57.745 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] SecurityLogWriter is created.
[vm_3][info 2016/08/11 15:55:57.749 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Running in client mode
[vm_3][info 2016/08/11 15:55:57.754 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Updating membership port. Port changed from 0 to 33,707. ID is now
venezuela(3572:loner):0:31bbd17b
[vm_2][info 2016/08/11 15:55:57.745 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$33/587716782.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$33/587716782@362a085b
[vm_2][debug 2016/08/11 15:55:57.747 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Changing level for Logger 'com.gemstone.gemfire.security' from TRACE
to TRACE
[vm_2][debug 2016/08/11 15:55:57.747 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] skipping banner - Locator.inhibitDMBanner is set to true
[vm_2][debug 2016/08/11 15:55:57.747 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] SecurityLogWriter is created.
[vm_2][info 2016/08/11 15:55:57.755 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Running in client mode
[info 2016/08/11 15:55:57.758 PDT <ServerConnection on port 60187 Thread 0>
tid=0xf0] Logging in key1User
[info 2016/08/11 15:55:57.759 PDT <ServerConnection on port 60187 Thread 0>
tid=0xf0] Enabling session validation scheduler...
[info 2016/08/11 15:55:57.759 PDT <ServerConnection on port 60187 Thread 0>
tid=0xf0]
com.gemstone.gemfire.internal.cache.tier.sockets.ClientUserAuths@34d5fe1d
[info 2016/08/11 15:55:57.767 PDT <Handshaker 0.0.0.0/0.0.0.0:60187 Thread 0>
tid=0xef] Initializing region
_gfe_non_durable_client_with_id_venezuela(3572:loner):33707:31bbd17b_1_queue
[info 2016/08/11 15:55:57.767 PDT <Handshaker 0.0.0.0/0.0.0.0:60187 Thread 0>
tid=0xef] Initialization of region
_gfe_non_durable_client_with_id_venezuela(3572:loner):33707:31bbd17b_1_queue
completed
[info 2016/08/11 15:55:57.768 PDT <Handshaker 0.0.0.0/0.0.0.0:60187 Thread 0>
tid=0xef] Entry expiry tasks disabled because the queue became primary. Old
messageTimeToLive was: 180
[vm_3][info 2016/08/11 15:55:57.770 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Pool DEFAULT started with multiuser-authentication=false
[debug 2016/08/11 15:55:57.772 PDT <Handshaker 0.0.0.0/0.0.0.0:60187 Thread 0>
tid=0xef] CacheClientNotifier: verifying credentials for proxyID:
identity(venezuela(3572:loner):33707:31bbd17b,connection=1
[info 2016/08/11 15:55:57.772 PDT <Handshaker 0.0.0.0/0.0.0.0:60187 Thread 0>
tid=0xef] Logging in key1User
[vm_3][info 2016/08/11 15:55:57.779 PDT <Cache Client Updater Thread on
venezuela(3448:loner):60187:16bbd17b port 60187> tid=0x181e] Cache Client
Updater Thread on venezuela(3448:loner):60187:16bbd17b port 60187
(localhost:60187) : ready to process messages.
[info 2016/08/11 15:55:57.780 PDT <ServerConnection on port 60187 Thread 0>
tid=0xf0] key1User not authorized for DATA:READ:AuthRegion
[info 2016/08/11 15:55:57.783 PDT <ServerConnection on port 60187 Thread 0>
tid=0xf0] key1User not authorized for DATA:READ:AuthRegion
[vm_3][info 2016/08/11 15:55:57.785 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$67/2093533096.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$67/2093533096@54031ed6
(took 41 ms)
[vm_2][info 2016/08/11 15:55:57.781 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Updating membership port. Port changed from 0 to 33,710. ID is now
venezuela(3565:loner):0:33bbd17b
[vm_1][info 2016/08/11 15:55:57.787 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$46/1711500041.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$46/1711500041@771c0eab
[vm_1][debug 2016/08/11 15:55:57.788 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Changing level for Logger 'com.gemstone.gemfire.security' from TRACE
to TRACE
[vm_1][debug 2016/08/11 15:55:57.789 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] skipping banner - Locator.inhibitDMBanner is set to true
[vm_1][debug 2016/08/11 15:55:57.789 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] SecurityLogWriter is created.
[vm_1][info 2016/08/11 15:55:57.792 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Running in client mode
[info 2016/08/11 15:55:57.800 PDT <ServerConnection on port 60187 Thread 3>
tid=0xf7] Logging in authRegionUser
[info 2016/08/11 15:55:57.801 PDT <ServerConnection on port 60187 Thread 3>
tid=0xf7]
com.gemstone.gemfire.internal.cache.tier.sockets.ClientUserAuths@67bdad80
[vm_1][info 2016/08/11 15:55:57.802 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Updating membership port. Port changed from 0 to 33,712. ID is now
venezuela(3560:loner):0:5dbbd17b
[info 2016/08/11 15:55:57.805 PDT <Handshaker 0.0.0.0/0.0.0.0:60187 Thread 2>
tid=0xf9] Initializing region
_gfe_non_durable_client_with_id_venezuela(3565:loner):33710:33bbd17b_1_queue
[info 2016/08/11 15:55:57.805 PDT <Handshaker 0.0.0.0/0.0.0.0:60187 Thread 2>
tid=0xf9] Initialization of region
_gfe_non_durable_client_with_id_venezuela(3565:loner):33710:33bbd17b_1_queue
completed
[info 2016/08/11 15:55:57.809 PDT <Handshaker 0.0.0.0/0.0.0.0:60187 Thread 2>
tid=0xf9] Entry expiry tasks disabled because the queue became primary. Old
messageTimeToLive was: 180
[debug 2016/08/11 15:55:57.811 PDT <Handshaker 0.0.0.0/0.0.0.0:60187 Thread 2>
tid=0xf9] CacheClientNotifier: verifying credentials for proxyID:
identity(venezuela(3565:loner):33710:33bbd17b,connection=1
[info 2016/08/11 15:55:57.811 PDT <Handshaker 0.0.0.0/0.0.0.0:60187 Thread 2>
tid=0xf9] Logging in authRegionUser
[info 2016/08/11 15:55:57.812 PDT <ServerConnection on port 60187 Thread 5>
tid=0xfb] Logging in stranger
[info 2016/08/11 15:55:57.816 PDT <ServerConnection on port 60187 Thread 4>
tid=0xfa] Logging in stranger
[info 2016/08/11 15:55:57.816 PDT <ServerConnection on port 60187 Thread 4>
tid=0xfa]
com.gemstone.gemfire.internal.cache.tier.sockets.ClientUserAuths@62a72368
[info 2016/08/11 15:55:57.818 PDT <ServerConnection on port 60187 Thread 5>
tid=0xfb]
com.gemstone.gemfire.internal.cache.tier.sockets.ClientUserAuths@62a72368
[info 2016/08/11 15:55:57.821 PDT <Handshaker 0.0.0.0/0.0.0.0:60187 Thread 2>
tid=0xf9] Initializing region
_gfe_non_durable_client_with_id_venezuela(3560:loner):33712:5dbbd17b_1_queue
[info 2016/08/11 15:55:57.821 PDT <Handshaker 0.0.0.0/0.0.0.0:60187 Thread 2>
tid=0xf9] Initialization of region
_gfe_non_durable_client_with_id_venezuela(3560:loner):33712:5dbbd17b_1_queue
completed
[vm_1][info 2016/08/11 15:55:57.822 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Pool DEFAULT started with multiuser-authentication=false
[info 2016/08/11 15:55:57.822 PDT <Handshaker 0.0.0.0/0.0.0.0:60187 Thread 2>
tid=0xf9] Entry expiry tasks disabled because the queue became primary. Old
messageTimeToLive was: 180
[debug 2016/08/11 15:55:57.822 PDT <Handshaker 0.0.0.0/0.0.0.0:60187 Thread 2>
tid=0xf9] CacheClientNotifier: verifying credentials for proxyID:
identity(venezuela(3560:loner):33712:5dbbd17b,connection=1
[info 2016/08/11 15:55:57.823 PDT <Handshaker 0.0.0.0/0.0.0.0:60187 Thread 2>
tid=0xf9] Logging in stranger
[vm_2][info 2016/08/11 15:55:57.810 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Pool DEFAULT started with multiuser-authentication=false
[vm_2][info 2016/08/11 15:55:57.820 PDT <Cache Client Updater Thread on
venezuela(3448:loner):60187:16bbd17b port 60187> tid=0x1b29] Cache Client
Updater Thread on venezuela(3448:loner):60187:16bbd17b port 60187
(localhost:60187) : ready to process messages.
[vm_1][info 2016/08/11 15:55:57.825 PDT <Cache Client Updater Thread on
venezuela(3448:loner):60187:16bbd17b port 60187> tid=0x1dd5] Cache Client
Updater Thread on venezuela(3448:loner):60187:16bbd17b port 60187
(localhost:60187) : ready to process messages.
[vm_2][info 2016/08/11 15:55:57.826 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$33/587716782.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$33/587716782@362a085b
(took 81 ms)
[info 2016/08/11 15:55:57.829 PDT <ServerConnection on port 60187 Thread 4>
tid=0xfa] stranger not authorized for DATA:READ:AuthRegion
[vm_1][info 2016/08/11 15:55:57.830 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$46/1711500041.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$46/1711500041@771c0eab
(took 42 ms)
[vm_1][info 2016/08/11 15:55:57.831 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$37/1871929006.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$37/1871929006@5eb6d72c
[vm_1][info 2016/08/11 15:55:57.832 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] GemFireCache[id = 63489693; isClosing = true; isShutDownAll = false;
created = Thu Aug 11 15:55:57 PDT 2016; server = false; copyOnRead = false;
lockLease = 120; lockTimeout = 60]: Now closing.
[info 2016/08/11 15:55:57.835 PDT <ServerConnection on port 60187 Thread 4>
tid=0xfa] stranger not authorized for DATA:READ:AuthRegion
[vm_1][warn 2016/08/11 15:55:57.836 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Problem removing all interest on region=/AuthRegion
interestType=REGEX :The cache is closed.
[vm_1][info 2016/08/11 15:55:57.837 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Destroying connection pool DEFAULT
[vm_1][info 2016/08/11 15:55:57.843 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$37/1871929006.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$37/1871929006@5eb6d72c
(took 11 ms)
[vm_2][info 2016/08/11 15:55:57.843 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$31/802889187.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$31/802889187@377e4903
[vm_2][info 2016/08/11 15:55:57.843 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] GemFireCache[id = 708426261; isClosing = true; isShutDownAll = false;
created = Thu Aug 11 15:55:57 PDT 2016; server = false; copyOnRead = false;
lockLease = 120; lockTimeout = 60]: Now closing.
[vm_2][info 2016/08/11 15:55:57.846 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Destroying connection pool DEFAULT
[vm_2][info 2016/08/11 15:55:57.851 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$31/802889187.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$31/802889187@377e4903
(took 7 ms)
[vm_3][info 2016/08/11 15:55:57.851 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$61/1581065677.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$61/1581065677@4557b8aa
[vm_3][info 2016/08/11 15:55:57.851 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] GemFireCache[id = 332241857; isClosing = true; isShutDownAll = false;
created = Thu Aug 11 15:55:57 PDT 2016; server = false; copyOnRead = false;
lockLease = 120; lockTimeout = 60]: Now closing.
[info 2016/08/11 15:55:57.856 PDT <ServerConnection on port 60187 Thread 0>
tid=0xf0] key1User not authorized for DATA:READ:AuthRegion
[vm_3][warn 2016/08/11 15:55:57.858 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Problem removing all interest on region=/AuthRegion
interestType=REGEX :The cache is closed.
[vm_3][info 2016/08/11 15:55:57.858 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Destroying connection pool DEFAULT
[vm_3][info 2016/08/11 15:55:57.863 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$61/1581065677.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$61/1581065677@4557b8aa
(took 11 ms)
[info 2016/08/11 15:55:57.866 PDT <Test worker> tid=0xa] GemFireCache[id =
482664898; isClosing = true; isShutDownAll = false; created = Thu Aug 11
15:55:57 PDT 2016; server = false; copyOnRead = false; lockLease = 120;
lockTimeout = 60]: Now closing.
[info 2016/08/11 15:55:57.866 PDT <Test worker> tid=0xa] Cache server on port
60,187 is shutting down.
[info 2016/08/11 15:55:57.867 PDT <Queue Removal Thread> tid=0xf5] The
QueueRemovalThread is done.
[vm_1][info 2016/08/11 15:55:57.870 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/2030275699.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/2030275699@9ac4e43
[vm_1][info 2016/08/11 15:55:57.871 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/2030275699.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/2030275699@9ac4e43
(took 0 ms)
[vm_2][info 2016/08/11 15:55:57.871 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/594604168.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/594604168@36da73a7
[vm_2][info 2016/08/11 15:55:57.871 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/594604168.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/594604168@36da73a7
(took 0 ms)
[vm_3][info 2016/08/11 15:55:57.872 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$18/1252408301.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$18/1252408301@2f849c33
[vm_3][info 2016/08/11 15:55:57.872 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$18/1252408301.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$18/1252408301@2f849c33
(took 0 ms)
[vm_1][info 2016/08/11 15:55:57.873 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownCreationStackGenerator)
[vm_1][info 2016/08/11 15:55:57.874 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownCreationStackGenerator) (took 0 ms)
[vm_2][info 2016/08/11 15:55:57.874 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownCreationStackGenerator)
[vm_2][info 2016/08/11 15:55:57.874 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownCreationStackGenerator) (took 0 ms)
[vm_3][info 2016/08/11 15:55:57.874 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownCreationStackGenerator)
[vm_3][info 2016/08/11 15:55:57.874 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownCreationStackGenerator) (took 0 ms)
[vm_2][info 2016/08/11 15:55:57.877 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownVM)
[vm_2][info 2016/08/11 15:55:57.877 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownVM) (took 0 ms)
[vm_1][info 2016/08/11 15:55:57.877 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownVM)
[vm_3][info 2016/08/11 15:55:57.878 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownVM)
[vm_3][info 2016/08/11 15:55:57.878 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownVM) (took 0 ms)
[vm_1][info 2016/08/11 15:55:57.877 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownVM) (took 0 ms)
[locator][info 2016/08/11 15:55:57.878 PDT <RMI TCP Connection(3)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$16/1967519806.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$16/1967519806@480d0319
[locator][info 2016/08/11 15:55:57.878 PDT <RMI TCP Connection(3)-10.118.32.90>
tid=0x12] Got result: null
[locator] from
com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$16/1967519806.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$16/1967519806@480d0319
(took 0 ms)
Previously run tests: [PRDistTXDUnitTest, DistTXWithDeltaDUnitTest,
DistTXPersistentDebugDUnitTest, PersistentPartitionedRegionWithDistTXDUnitTest,
DistTXOrderDUnitTest, PRDistTXWithVersionsDUnitTest, CacheMapDistTXDUnitTest,
DistTXRestrictionsDUnitTest, DistributedTransactionDUnitTest,
DistTXDebugDUnitTest, IntegratedClientGetEntryAuthDistributedTest,
PDXGfshPostProcessorOnRemoteServerTest,
IntegratedClientGetPutAuthDistributedTest,
IntegratedClientRegisterInterestAuthDistributedTest]
[vm_1][info 2016/08/11 15:55:57.880 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(setupVM)
[vm_1][info 2016/08/11 15:55:57.880 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(setupVM) (took 0 ms)
[vm_2][info 2016/08/11 15:55:57.881 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(setupVM)
[vm_2][info 2016/08/11 15:55:57.881 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(setupVM) (took 0 ms)
[vm_3][info 2016/08/11 15:55:57.881 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(setupVM)
[vm_3][info 2016/08/11 15:55:57.881 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(setupVM) (took 0 ms)
[setup] START TEST
IntegratedClientRegisterInterestAuthDistributedTest.testRegisterInterestList
distributed system properties: {mcast-port=0, security-log-level=finest,
log-level=info, disable-auto-reconnect=true,
enable-cluster-configuration=false,
security-manager=org.apache.geode.security.templates.SampleSecurityManager,
security-pdx=false, locators=, use-cluster-configuration=false,
security-json=com/gemstone/gemfire/management/internal/security/clientServer.json}
[debug 2016/08/11 15:55:57.884 PDT <Test worker> tid=0xa] Changing level for
Logger 'com.gemstone.gemfire.security' from TRACE to TRACE
[debug 2016/08/11 15:55:57.885 PDT <Test worker> tid=0xa] skipping banner -
Locator.inhibitDMBanner is set to true
[debug 2016/08/11 15:55:57.885 PDT <Test worker> tid=0xa] SecurityLogWriter is
created.
[info 2016/08/11 15:55:57.891 PDT <Test worker> tid=0xa] Running in local mode
since no locators were specified.
[info 2016/08/11 15:55:57.896 PDT <Test worker> tid=0xa] Initializing region
_monitoringRegion_10.118.32.90<v-1>0
[info 2016/08/11 15:55:57.897 PDT <Test worker> tid=0xa] Initialization of
region _monitoringRegion_10.118.32.90<v-1>0 completed
[info 2016/08/11 15:55:57.903 PDT <Test worker> tid=0xa] Initializing region
AuthRegion
[info 2016/08/11 15:55:57.903 PDT <Test worker> tid=0xa] Initialization of
region AuthRegion completed
[info 2016/08/11 15:55:57.904 PDT <Test worker> tid=0xa] Updating membership
port. Port changed from 0 to 43,972. ID is now
venezuela(3448:loner):0:bdbbd17b
[info 2016/08/11 15:55:57.904 PDT <Test worker> tid=0xa] Cache server
connection listener bound to address 0.0.0.0/0.0.0.0:43972 with backlog 1,000.
[info 2016/08/11 15:55:57.905 PDT <Test worker> tid=0xa]
ClientHealthMonitorThread maximum allowed time between pings: 60,000
[info 2016/08/11 15:55:57.906 PDT <Test worker> tid=0xa] CacheServer
Configuration: port=43972 max-connections=800 max-threads=0
notify-by-subscription=true socket-buffer-size=32768
maximum-time-between-pings=60000 maximum-message-count=230000
message-time-to-live=180 eviction-policy=none capacity=1 overflow directory=.
groups=[] loadProbe=ConnectionCountProbe loadPollInterval=5000 tcpNoDelay=true
[vm_1][info 2016/08/11 15:55:57.913 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$48/526572850.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$48/526572850@e92c459
[vm_3][info 2016/08/11 15:55:57.913 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$70/1286599278.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$70/1286599278@90f16be
[vm_3][debug 2016/08/11 15:55:57.915 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Changing level for Logger 'com.gemstone.gemfire.security' from TRACE
to TRACE
[vm_3][debug 2016/08/11 15:55:57.915 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] skipping banner - Locator.inhibitDMBanner is set to true
[vm_3][debug 2016/08/11 15:55:57.915 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] SecurityLogWriter is created.
[vm_1][debug 2016/08/11 15:55:57.915 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Changing level for Logger 'com.gemstone.gemfire.security' from TRACE
to TRACE
[vm_1][debug 2016/08/11 15:55:57.915 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] skipping banner - Locator.inhibitDMBanner is set to true
[vm_1][debug 2016/08/11 15:55:57.915 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] SecurityLogWriter is created.
[vm_2][info 2016/08/11 15:55:57.911 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$34/511855514.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$34/511855514@6611154f
[vm_2][debug 2016/08/11 15:55:57.912 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Changing level for Logger 'com.gemstone.gemfire.security' from TRACE
to TRACE
[vm_2][debug 2016/08/11 15:55:57.914 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] skipping banner - Locator.inhibitDMBanner is set to true
[vm_2][debug 2016/08/11 15:55:57.914 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] SecurityLogWriter is created.
[vm_2][info 2016/08/11 15:55:57.917 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Running in client mode
[vm_3][info 2016/08/11 15:55:57.918 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Running in client mode
[vm_1][info 2016/08/11 15:55:57.919 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Running in client mode
[vm_3][info 2016/08/11 15:55:57.921 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Updating membership port. Port changed from 0 to 54,283. ID is now
venezuela(3572:loner):0:dbbbd17b
[vm_2][info 2016/08/11 15:55:57.925 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Updating membership port. Port changed from 0 to 54,285. ID is now
venezuela(3565:loner):0:dabbd17b
[vm_1][info 2016/08/11 15:55:57.927 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Updating membership port. Port changed from 0 to 54,287. ID is now
venezuela(3560:loner):0:dbbbd17b
[info 2016/08/11 15:55:57.929 PDT <ServerConnection on port 43972 Thread 0>
tid=0x11a] Logging in key1User
[info 2016/08/11 15:55:57.930 PDT <ServerConnection on port 43972 Thread 0>
tid=0x11a] Enabling session validation scheduler...
[info 2016/08/11 15:55:57.931 PDT <ServerConnection on port 43972 Thread 0>
tid=0x11a]
com.gemstone.gemfire.internal.cache.tier.sockets.ClientUserAuths@652d9ecb
[info 2016/08/11 15:55:57.937 PDT <ServerConnection on port 43972 Thread 5>
tid=0x122] Logging in stranger
[info 2016/08/11 15:55:57.937 PDT <ServerConnection on port 43972 Thread 2>
tid=0x11e] Logging in authRegionUser
[info 2016/08/11 15:55:57.938 PDT <ServerConnection on port 43972 Thread 5>
tid=0x122]
com.gemstone.gemfire.internal.cache.tier.sockets.ClientUserAuths@252f3d4
[info 2016/08/11 15:55:57.938 PDT <ServerConnection on port 43972 Thread 2>
tid=0x11e]
com.gemstone.gemfire.internal.cache.tier.sockets.ClientUserAuths@21ef1dc9
[info 2016/08/11 15:55:57.938 PDT <ServerConnection on port 43972 Thread 3>
tid=0x11f] Logging in authRegionUser
[info 2016/08/11 15:55:57.938 PDT <ServerConnection on port 43972 Thread 3>
tid=0x11f]
com.gemstone.gemfire.internal.cache.tier.sockets.ClientUserAuths@21ef1dc9
[info 2016/08/11 15:55:57.938 PDT <Handshaker 0.0.0.0/0.0.0.0:43972 Thread 1>
tid=0x11c] Initializing region
_gfe_non_durable_client_with_id_venezuela(3572:loner):54283:dbbbd17b_1_queue
[info 2016/08/11 15:55:57.938 PDT <Handshaker 0.0.0.0/0.0.0.0:43972 Thread 1>
tid=0x11c] Initialization of region
_gfe_non_durable_client_with_id_venezuela(3572:loner):54283:dbbbd17b_1_queue
completed
[info 2016/08/11 15:55:57.940 PDT <Handshaker 0.0.0.0/0.0.0.0:43972 Thread 1>
tid=0x11c] Entry expiry tasks disabled because the queue became primary. Old
messageTimeToLive was: 180
[info 2016/08/11 15:55:57.941 PDT <Handshaker 0.0.0.0/0.0.0.0:43972 Thread 0>
tid=0x119] Initializing region
_gfe_non_durable_client_with_id_venezuela(3565:loner):54285:dabbd17b_1_queue
[info 2016/08/11 15:55:57.942 PDT <Handshaker 0.0.0.0/0.0.0.0:43972 Thread 0>
tid=0x119] Initialization of region
_gfe_non_durable_client_with_id_venezuela(3565:loner):54285:dabbd17b_1_queue
completed
[info 2016/08/11 15:55:57.944 PDT <Handshaker 0.0.0.0/0.0.0.0:43972 Thread 0>
tid=0x119] Entry expiry tasks disabled because the queue became primary. Old
messageTimeToLive was: 180
[debug 2016/08/11 15:55:57.944 PDT <Handshaker 0.0.0.0/0.0.0.0:43972 Thread 0>
tid=0x119] CacheClientNotifier: verifying credentials for proxyID:
identity(venezuela(3565:loner):54285:dabbd17b,connection=1
[info 2016/08/11 15:55:57.944 PDT <Handshaker 0.0.0.0/0.0.0.0:43972 Thread 0>
tid=0x119] Logging in authRegionUser
[info 2016/08/11 15:55:57.945 PDT <ServerConnection on port 43972 Thread 0>
tid=0x11a] key1User not authorized for DATA:READ:AuthRegion
[vm_3][info 2016/08/11 15:55:57.941 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Pool DEFAULT started with multiuser-authentication=false
[vm_3][info 2016/08/11 15:55:57.942 PDT <Cache Client Updater Thread on
venezuela(3448:loner):43972:bdbbd17b port 43972> tid=0x1832] Cache Client
Updater Thread on venezuela(3448:loner):43972:bdbbd17b port 43972
(localhost:43972) : ready to process messages.
[vm_3][info 2016/08/11 15:55:57.946 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$70/1286599278.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$70/1286599278@90f16be
(took 32 ms)
[vm_2][info 2016/08/11 15:55:57.945 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Pool DEFAULT started with multiuser-authentication=false
[debug 2016/08/11 15:55:57.947 PDT <Handshaker 0.0.0.0/0.0.0.0:43972 Thread 1>
tid=0x11c] CacheClientNotifier: verifying credentials for proxyID:
identity(venezuela(3572:loner):54283:dbbbd17b,connection=1
[info 2016/08/11 15:55:57.947 PDT <Handshaker 0.0.0.0/0.0.0.0:43972 Thread 1>
tid=0x11c] Logging in key1User
[vm_2][info 2016/08/11 15:55:57.948 PDT <Cache Client Updater Thread on
venezuela(3448:loner):43972:bdbbd17b port 43972> tid=0x1b3c] Cache Client
Updater Thread on venezuela(3448:loner):43972:bdbbd17b port 43972
(localhost:43972) : ready to process messages.
[info 2016/08/11 15:55:57.948 PDT <Handshaker 0.0.0.0/0.0.0.0:43972 Thread 2>
tid=0x126] Initializing region
_gfe_non_durable_client_with_id_venezuela(3560:loner):54287:dbbbd17b_1_queue
[info 2016/08/11 15:55:57.949 PDT <Handshaker 0.0.0.0/0.0.0.0:43972 Thread 2>
tid=0x126] Initialization of region
_gfe_non_durable_client_with_id_venezuela(3560:loner):54287:dbbbd17b_1_queue
completed
[vm_1][info 2016/08/11 15:55:57.949 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Pool DEFAULT started with multiuser-authentication=false
[vm_1][info 2016/08/11 15:55:57.950 PDT <Cache Client Updater Thread on
venezuela(3448:loner):43972:bdbbd17b port 43972> tid=0x1deb] Cache Client
Updater Thread on venezuela(3448:loner):43972:bdbbd17b port 43972
(localhost:43972) : ready to process messages.
[vm_2][info 2016/08/11 15:55:57.951 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$34/511855514.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$34/511855514@6611154f
(took 39 ms)
[info 2016/08/11 15:55:57.950 PDT <Handshaker 0.0.0.0/0.0.0.0:43972 Thread 2>
tid=0x126] Entry expiry tasks disabled because the queue became primary. Old
messageTimeToLive was: 180
[debug 2016/08/11 15:55:57.951 PDT <Handshaker 0.0.0.0/0.0.0.0:43972 Thread 2>
tid=0x126] CacheClientNotifier: verifying credentials for proxyID:
identity(venezuela(3560:loner):54287:dbbbd17b,connection=1
[info 2016/08/11 15:55:57.951 PDT <Handshaker 0.0.0.0/0.0.0.0:43972 Thread 2>
tid=0x126] Logging in stranger
[info 2016/08/11 15:55:57.955 PDT <ServerConnection on port 43972 Thread 4>
tid=0x120] stranger not authorized for DATA:READ:AuthRegion
[vm_1][info 2016/08/11 15:55:57.956 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$48/526572850.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$48/526572850@e92c459
(took 43 ms)
[vm_1][info 2016/08/11 15:55:57.958 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$37/1871929006.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$37/1871929006@5eb6d72c
[vm_1][info 2016/08/11 15:55:57.959 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] GemFireCache[id = 1030007132; isClosing = true; isShutDownAll =
false; created = Thu Aug 11 15:55:57 PDT 2016; server = false; copyOnRead =
false; lockLease = 120; lockTimeout = 60]: Now closing.
[info 2016/08/11 15:55:57.959 PDT <ServerConnection on port 43972 Thread 4>
tid=0x120] stranger not authorized for DATA:READ:AuthRegion:UNREGISTER ALL
INTEREST
[vm_1][warn 2016/08/11 15:55:57.961 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Problem removing all interest on region=/AuthRegion interestType=KEY
:The cache is closed.
[vm_1][info 2016/08/11 15:55:57.962 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Destroying connection pool DEFAULT
[vm_1][info 2016/08/11 15:55:57.967 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$37/1871929006.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$37/1871929006@5eb6d72c
(took 8 ms)
[vm_2][info 2016/08/11 15:55:57.969 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$31/802889187.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$31/802889187@377e4903
[vm_2][info 2016/08/11 15:55:57.969 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] GemFireCache[id = 100293340; isClosing = true; isShutDownAll = false;
created = Thu Aug 11 15:55:57 PDT 2016; server = false; copyOnRead = false;
lockLease = 120; lockTimeout = 60]: Now closing.
[vm_2][info 2016/08/11 15:55:57.970 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Destroying connection pool DEFAULT
[vm_2][info 2016/08/11 15:55:57.974 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$31/802889187.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$31/802889187@377e4903
(took 4 ms)
[vm_3][info 2016/08/11 15:55:57.974 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$61/1581065677.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$61/1581065677@4557b8aa
[vm_3][info 2016/08/11 15:55:57.974 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] GemFireCache[id = 867971286; isClosing = true; isShutDownAll = false;
created = Thu Aug 11 15:55:57 PDT 2016; server = false; copyOnRead = false;
lockLease = 120; lockTimeout = 60]: Now closing.
[info 2016/08/11 15:55:57.975 PDT <ServerConnection on port 43972 Thread 0>
tid=0x11a] key1User not authorized for DATA:READ:AuthRegion:UNREGISTER ALL
INTEREST
[vm_3][warn 2016/08/11 15:55:57.976 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Problem removing all interest on region=/AuthRegion interestType=KEY
:The cache is closed.
[vm_3][info 2016/08/11 15:55:57.976 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Destroying connection pool DEFAULT
[vm_3][info 2016/08/11 15:55:57.979 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$61/1581065677.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$61/1581065677@4557b8aa
(took 4 ms)
[info 2016/08/11 15:55:57.981 PDT <Test worker> tid=0xa] GemFireCache[id =
595337628; isClosing = true; isShutDownAll = false; created = Thu Aug 11
15:55:57 PDT 2016; server = false; copyOnRead = false; lockLease = 120;
lockTimeout = 60]: Now closing.
[info 2016/08/11 15:55:57.981 PDT <Test worker> tid=0xa] Cache server on port
43,972 is shutting down.
[info 2016/08/11 15:55:57.983 PDT <Queue Removal Thread> tid=0x124] The
QueueRemovalThread is done.
[vm_1][info 2016/08/11 15:55:57.987 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/2030275699.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/2030275699@9ac4e43
[vm_1][info 2016/08/11 15:55:57.988 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/2030275699.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/2030275699@9ac4e43
(took 0 ms)
[vm_2][info 2016/08/11 15:55:57.989 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/594604168.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/594604168@36da73a7
[vm_2][info 2016/08/11 15:55:57.989 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/594604168.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/594604168@36da73a7
(took 0 ms)
[vm_3][info 2016/08/11 15:55:57.990 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$18/1252408301.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$18/1252408301@2f849c33
[vm_3][info 2016/08/11 15:55:57.990 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$18/1252408301.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$18/1252408301@2f849c33
(took 0 ms)
[vm_1][info 2016/08/11 15:55:57.992 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownCreationStackGenerator)
[vm_1][info 2016/08/11 15:55:57.992 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownCreationStackGenerator) (took 0 ms)
[vm_2][info 2016/08/11 15:55:57.992 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownCreationStackGenerator)
[vm_2][info 2016/08/11 15:55:57.993 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownCreationStackGenerator) (took 0 ms)
[vm_3][info 2016/08/11 15:55:57.994 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownCreationStackGenerator)
[vm_3][info 2016/08/11 15:55:57.994 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownCreationStackGenerator) (took 0 ms)
[vm_1][info 2016/08/11 15:55:57.997 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownVM)
[vm_1][info 2016/08/11 15:55:57.997 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownVM) (took 0 ms)
[vm_2][info 2016/08/11 15:55:57.997 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownVM)
[vm_2][info 2016/08/11 15:55:57.998 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownVM) (took 0 ms)
[vm_3][info 2016/08/11 15:55:57.998 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownVM)
[vm_3][info 2016/08/11 15:55:57.998 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownVM) (took 0 ms)
[locator][info 2016/08/11 15:55:57.999 PDT <RMI TCP Connection(3)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$16/1967519806.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$16/1967519806@480d0319
[locator][info 2016/08/11 15:55:57.999 PDT <RMI TCP Connection(3)-10.118.32.90>
tid=0x12] Got result: null
[locator] from
com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$16/1967519806.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.internal.JUnit4DistributedTestCase$$Lambda$16/1967519806@480d0319
(took 0 ms)
Previously run tests: [PRDistTXDUnitTest, DistTXWithDeltaDUnitTest,
DistTXPersistentDebugDUnitTest, PersistentPartitionedRegionWithDistTXDUnitTest,
DistTXOrderDUnitTest, PRDistTXWithVersionsDUnitTest, CacheMapDistTXDUnitTest,
DistTXRestrictionsDUnitTest, DistributedTransactionDUnitTest,
DistTXDebugDUnitTest, IntegratedClientGetEntryAuthDistributedTest,
PDXGfshPostProcessorOnRemoteServerTest,
IntegratedClientGetPutAuthDistributedTest,
IntegratedClientRegisterInterestAuthDistributedTest]
[vm_2][info 2016/08/11 15:55:58.004 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(setupVM)
[vm_2][info 2016/08/11 15:55:58.005 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_1][info 2016/08/11 15:55:58.004 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(setupVM)
[vm_1][info 2016/08/11 15:55:58.004 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(setupVM) (took 0 ms)
[vm_2] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(setupVM) (took 0 ms)
[vm_3][info 2016/08/11 15:55:58.005 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(setupVM)
[vm_3][info 2016/08/11 15:55:58.005 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(setupVM) (took 0 ms)
[setup] START TEST
IntegratedClientRegisterInterestAuthDistributedTest.testRegisterInterest
distributed system properties: {mcast-port=0, security-log-level=finest,
log-level=info, disable-auto-reconnect=true,
enable-cluster-configuration=false,
security-manager=org.apache.geode.security.templates.SampleSecurityManager,
security-pdx=false, locators=, use-cluster-configuration=false,
security-json=com/gemstone/gemfire/management/internal/security/clientServer.json}
[debug 2016/08/11 15:55:58.009 PDT <Test worker> tid=0xa] Changing level for
Logger 'com.gemstone.gemfire.security' from TRACE to TRACE
[debug 2016/08/11 15:55:58.009 PDT <Test worker> tid=0xa] skipping banner -
Locator.inhibitDMBanner is set to true
[debug 2016/08/11 15:55:58.009 PDT <Test worker> tid=0xa] SecurityLogWriter is
created.
[info 2016/08/11 15:55:58.022 PDT <Test worker> tid=0xa] Running in local mode
since no locators were specified.
[info 2016/08/11 15:55:58.026 PDT <Test worker> tid=0xa] Initializing region
_monitoringRegion_10.118.32.90<v-1>0
[info 2016/08/11 15:55:58.027 PDT <Test worker> tid=0xa] Initialization of
region _monitoringRegion_10.118.32.90<v-1>0 completed
[info 2016/08/11 15:55:58.031 PDT <Test worker> tid=0xa] Initializing region
AuthRegion
[info 2016/08/11 15:55:58.031 PDT <Test worker> tid=0xa] Initialization of
region AuthRegion completed
[info 2016/08/11 15:55:58.032 PDT <Test worker> tid=0xa] Updating membership
port. Port changed from 0 to 48,141. ID is now
venezuela(3448:loner):0:39bcd17b
[info 2016/08/11 15:55:58.032 PDT <Test worker> tid=0xa] Cache server
connection listener bound to address 0.0.0.0/0.0.0.0:48141 with backlog 1,000.
[info 2016/08/11 15:55:58.033 PDT <Test worker> tid=0xa]
ClientHealthMonitorThread maximum allowed time between pings: 60,000
[info 2016/08/11 15:55:58.034 PDT <Test worker> tid=0xa] CacheServer
Configuration: port=48141 max-connections=800 max-threads=0
notify-by-subscription=true socket-buffer-size=32768
maximum-time-between-pings=60000 maximum-message-count=230000
message-time-to-live=180 eviction-policy=none capacity=1 overflow directory=.
groups=[] loadProbe=ConnectionCountProbe loadPollInterval=5000 tcpNoDelay=true
[vm_1][info 2016/08/11 15:55:58.039 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$50/348163231.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$50/348163231@5d650770
[vm_1][debug 2016/08/11 15:55:58.040 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Changing level for Logger 'com.gemstone.gemfire.security' from TRACE
to TRACE
[vm_1][debug 2016/08/11 15:55:58.040 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] skipping banner - Locator.inhibitDMBanner is set to true
[vm_1][debug 2016/08/11 15:55:58.041 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] SecurityLogWriter is created.
[vm_2][info 2016/08/11 15:55:58.044 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$35/987153739.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$35/987153739@69d68bf3
[vm_3][info 2016/08/11 15:55:58.039 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$72/1051884709.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$72/1051884709@6a6dec3c
[vm_3][debug 2016/08/11 15:55:58.041 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Changing level for Logger 'com.gemstone.gemfire.security' from TRACE
to TRACE
[vm_3][debug 2016/08/11 15:55:58.041 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] skipping banner - Locator.inhibitDMBanner is set to true
[vm_3][debug 2016/08/11 15:55:58.041 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] SecurityLogWriter is created.
[vm_3][info 2016/08/11 15:55:58.046 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Running in client mode
[vm_2][debug 2016/08/11 15:55:58.048 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Changing level for Logger 'com.gemstone.gemfire.security' from TRACE
to TRACE
[vm_2][debug 2016/08/11 15:55:58.049 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] skipping banner - Locator.inhibitDMBanner is set to true
[vm_2][debug 2016/08/11 15:55:58.049 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] SecurityLogWriter is created.
[vm_1][info 2016/08/11 15:55:58.049 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Running in client mode
[vm_3][info 2016/08/11 15:55:58.049 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Updating membership port. Port changed from 0 to 51,581. ID is now
venezuela(3572:loner):0:59bcd17b
[vm_2][info 2016/08/11 15:55:58.053 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Running in client mode
[vm_1][info 2016/08/11 15:55:58.053 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Updating membership port. Port changed from 0 to 51,583. ID is now
venezuela(3560:loner):0:59bcd17b
[vm_2][info 2016/08/11 15:55:58.064 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Updating membership port. Port changed from 0 to 51,585. ID is now
venezuela(3565:loner):0:61bcd17b
[info 2016/08/11 15:55:58.069 PDT <ServerConnection on port 48141 Thread 0>
tid=0x144] Logging in key1User
[info 2016/08/11 15:55:58.069 PDT <ServerConnection on port 48141 Thread 0>
tid=0x144] Enabling session validation scheduler...
[info 2016/08/11 15:55:58.070 PDT <ServerConnection on port 48141 Thread 0>
tid=0x144]
com.gemstone.gemfire.internal.cache.tier.sockets.ClientUserAuths@1776f026
[info 2016/08/11 15:55:58.073 PDT <ServerConnection on port 48141 Thread 2>
tid=0x147] Logging in stranger
[info 2016/08/11 15:55:58.073 PDT <ServerConnection on port 48141 Thread 2>
tid=0x147]
com.gemstone.gemfire.internal.cache.tier.sockets.ClientUserAuths@3f28b918
[info 2016/08/11 15:55:58.074 PDT <ServerConnection on port 48141 Thread 4>
tid=0x14a] Logging in authRegionUser
[info 2016/08/11 15:55:58.074 PDT <ServerConnection on port 48141 Thread 4>
tid=0x14a]
com.gemstone.gemfire.internal.cache.tier.sockets.ClientUserAuths@b174bc6
[info 2016/08/11 15:55:58.075 PDT <ServerConnection on port 48141 Thread 3>
tid=0x149] Logging in key1User
[info 2016/08/11 15:55:58.075 PDT <ServerConnection on port 48141 Thread 3>
tid=0x149]
com.gemstone.gemfire.internal.cache.tier.sockets.ClientUserAuths@1776f026
[info 2016/08/11 15:55:58.071 PDT <ServerConnection on port 48141 Thread 1>
tid=0x146] Logging in stranger
[info 2016/08/11 15:55:58.082 PDT <ServerConnection on port 48141 Thread 1>
tid=0x146]
com.gemstone.gemfire.internal.cache.tier.sockets.ClientUserAuths@3f28b918
[warn 2016/08/11 15:55:58.085 PDT <JMX client heartbeat 2> tid=0xae] (tid=174
msgId=9) Failed to restart: java.io.IOException: Failed to get a RMI stub:
javax.naming.CommunicationException [Root exception is
java.rmi.NoSuchObjectException: no such object in table]
[info 2016/08/11 15:55:58.085 PDT <Handshaker 0.0.0.0/0.0.0.0:48141 Thread 2>
tid=0x14c] Initializing region
_gfe_non_durable_client_with_id_venezuela(3565:loner):51585:61bcd17b_1_queue
[info 2016/08/11 15:55:58.085 PDT <Handshaker 0.0.0.0/0.0.0.0:48141 Thread 2>
tid=0x14c] Initialization of region
_gfe_non_durable_client_with_id_venezuela(3565:loner):51585:61bcd17b_1_queue
completed
[info 2016/08/11 15:55:58.085 PDT <Handshaker 0.0.0.0/0.0.0.0:48141 Thread 1>
tid=0x145] Initializing region
_gfe_non_durable_client_with_id_venezuela(3572:loner):51581:59bcd17b_1_queue
[info 2016/08/11 15:55:58.086 PDT <Handshaker 0.0.0.0/0.0.0.0:48141 Thread 1>
tid=0x145] Initialization of region
_gfe_non_durable_client_with_id_venezuela(3572:loner):51581:59bcd17b_1_queue
completed
[vm_2][info 2016/08/11 15:55:58.087 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Pool DEFAULT started with multiuser-authentication=false
[fatal 2016/08/11 15:55:58.089 PDT <JMX client heartbeat 2> tid=0xae] (tid=174
msgId=10) No longer connected to localhost[20406].
[info 2016/08/11 15:55:58.091 PDT <Handshaker 0.0.0.0/0.0.0.0:48141 Thread 1>
tid=0x145] Entry expiry tasks disabled because the queue became primary. Old
messageTimeToLive was: 180
[vm_2][info 2016/08/11 15:55:58.091 PDT <Cache Client Updater Thread on
venezuela(3448:loner):48141:39bcd17b port 48141> tid=0x1b50] Cache Client
Updater Thread on venezuela(3448:loner):48141:39bcd17b port 48141
(localhost:48141) : ready to process messages.
[warn 2016/08/11 15:55:58.098 PDT <JMX client heartbeat 2> tid=0xae] (tid=174
msgId=11) Failed to call the method close():java.rmi.ConnectException:
Connection refused to host: 10.118.32.90; nested exception is:
java.net.ConnectException: Connection refused
[warn 2016/08/11 15:55:58.099 PDT <JMX client heartbeat 2> tid=0xae] (tid=174
msgId=12) Failed to check connection: java.rmi.NoSuchObjectException: no such
object in table
[warn 2016/08/11 15:55:58.099 PDT <JMX client heartbeat 2> tid=0xae] (tid=174
msgId=13) stopping
[vm_3][info 2016/08/11 15:55:58.093 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Pool DEFAULT started with multiuser-authentication=false
[vm_3][info 2016/08/11 15:55:58.096 PDT <Cache Client Updater Thread on
venezuela(3448:loner):48141:39bcd17b port 48141> tid=0x1847] Cache Client
Updater Thread on venezuela(3448:loner):48141:39bcd17b port 48141
(localhost:48141) : ready to process messages.
[info 2016/08/11 15:55:58.100 PDT <Handshaker 0.0.0.0/0.0.0.0:48141 Thread 0>
tid=0x143] Initializing region
_gfe_non_durable_client_with_id_venezuela(3560:loner):51583:59bcd17b_1_queue
[info 2016/08/11 15:55:58.100 PDT <Handshaker 0.0.0.0/0.0.0.0:48141 Thread 0>
tid=0x143] Initialization of region
_gfe_non_durable_client_with_id_venezuela(3560:loner):51583:59bcd17b_1_queue
completed
[info 2016/08/11 15:55:58.101 PDT <Handshaker 0.0.0.0/0.0.0.0:48141 Thread 0>
tid=0x143] Entry expiry tasks disabled because the queue became primary. Old
messageTimeToLive was: 180
[debug 2016/08/11 15:55:58.102 PDT <Handshaker 0.0.0.0/0.0.0.0:48141 Thread 0>
tid=0x143] CacheClientNotifier: verifying credentials for proxyID:
identity(venezuela(3560:loner):51583:59bcd17b,connection=1
[info 2016/08/11 15:55:58.102 PDT <Handshaker 0.0.0.0/0.0.0.0:48141 Thread 0>
tid=0x143] Logging in stranger
[vm_2][info 2016/08/11 15:55:58.103 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$35/987153739.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$35/987153739@69d68bf3
(took 58 ms)
[debug 2016/08/11 15:55:58.102 PDT <Handshaker 0.0.0.0/0.0.0.0:48141 Thread 1>
tid=0x145] CacheClientNotifier: verifying credentials for proxyID:
identity(venezuela(3572:loner):51581:59bcd17b,connection=1
[vm_1][info 2016/08/11 15:55:58.103 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Pool DEFAULT started with multiuser-authentication=false
[info 2016/08/11 15:55:58.102 PDT <Handshaker 0.0.0.0/0.0.0.0:48141 Thread 2>
tid=0x14c] Entry expiry tasks disabled because the queue became primary. Old
messageTimeToLive was: 180
[vm_1][info 2016/08/11 15:55:58.106 PDT <Cache Client Updater Thread on
venezuela(3448:loner):48141:39bcd17b port 48141> tid=0x1dff] Cache Client
Updater Thread on venezuela(3448:loner):48141:39bcd17b port 48141
(localhost:48141) : ready to process messages.
[debug 2016/08/11 15:55:58.107 PDT <Handshaker 0.0.0.0/0.0.0.0:48141 Thread 2>
tid=0x14c] CacheClientNotifier: verifying credentials for proxyID:
identity(venezuela(3565:loner):51585:61bcd17b,connection=1
[info 2016/08/11 15:55:58.103 PDT <ServerConnection on port 48141 Thread 0>
tid=0x144] key1User not authorized for DATA:READ:AuthRegion:key2
[info 2016/08/11 15:55:58.108 PDT <ServerConnection on port 48141 Thread 1>
tid=0x146] stranger not authorized for DATA:READ:AuthRegion:key3
[info 2016/08/11 15:55:58.107 PDT <Handshaker 0.0.0.0/0.0.0.0:48141 Thread 1>
tid=0x145] Logging in key1User
[info 2016/08/11 15:55:58.107 PDT <Handshaker 0.0.0.0/0.0.0.0:48141 Thread 2>
tid=0x14c] Logging in authRegionUser
[vm_1][info 2016/08/11 15:55:58.109 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$50/348163231.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$50/348163231@5d650770
(took 70 ms)
[vm_3][info 2016/08/11 15:55:58.110 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$72/1051884709.run
with 0 args on object:
com.gemstone.gemfire.security.IntegratedClientRegisterInterestAuthDistributedTest$$Lambda$72/1051884709@6a6dec3c
(took 71 ms)
[vm_1][info 2016/08/11 15:55:58.112 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$37/1871929006.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$37/1871929006@5eb6d72c
[vm_1][info 2016/08/11 15:55:58.112 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] GemFireCache[id = 779332955; isClosing = true; isShutDownAll = false;
created = Thu Aug 11 15:55:58 PDT 2016; server = false; copyOnRead = false;
lockLease = 120; lockTimeout = 60]: Now closing.
[info 2016/08/11 15:55:58.113 PDT <ServerConnection on port 48141 Thread 1>
tid=0x146] stranger not authorized for DATA:READ:AuthRegion:UNREGISTER ALL
INTEREST
[vm_1][warn 2016/08/11 15:55:58.114 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Problem removing all interest on region=/AuthRegion interestType=KEY
:The cache is closed.
[vm_1][info 2016/08/11 15:55:58.114 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Destroying connection pool DEFAULT
[vm_1][info 2016/08/11 15:55:58.120 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$37/1871929006.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$37/1871929006@5eb6d72c
(took 8 ms)
[vm_2][info 2016/08/11 15:55:58.121 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$31/802889187.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$31/802889187@377e4903
[vm_2][info 2016/08/11 15:55:58.121 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] GemFireCache[id = 1790916342; isClosing = true; isShutDownAll =
false; created = Thu Aug 11 15:55:58 PDT 2016; server = false; copyOnRead =
false; lockLease = 120; lockTimeout = 60]: Now closing.
[vm_2][info 2016/08/11 15:55:58.122 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Destroying connection pool DEFAULT
[vm_2][info 2016/08/11 15:55:58.129 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$31/802889187.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$31/802889187@377e4903
(took 7 ms)
[vm_3][info 2016/08/11 15:55:58.130 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$61/1581065677.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$61/1581065677@4557b8aa
[vm_3][info 2016/08/11 15:55:58.130 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] GemFireCache[id = 697526821; isClosing = true; isShutDownAll = false;
created = Thu Aug 11 15:55:58 PDT 2016; server = false; copyOnRead = false;
lockLease = 120; lockTimeout = 60]: Now closing.
[info 2016/08/11 15:55:58.131 PDT <ServerConnection on port 48141 Thread 0>
tid=0x144] key1User not authorized for DATA:READ:AuthRegion:UNREGISTER ALL
INTEREST
[vm_3][warn 2016/08/11 15:55:58.132 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Problem removing all interest on region=/AuthRegion interestType=KEY
:The cache is closed.
[vm_3][info 2016/08/11 15:55:58.133 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Destroying connection pool DEFAULT
[vm_3][info 2016/08/11 15:55:58.141 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$61/1581065677.run
with 0 args on object:
com.gemstone.gemfire.security.AbstractSecureServerDUnitTest$$Lambda$61/1581065677@4557b8aa
(took 11 ms)
[info 2016/08/11 15:55:58.142 PDT <Test worker> tid=0xa] GemFireCache[id =
1266882533; isClosing = true; isShutDownAll = false; created = Thu Aug 11
15:55:58 PDT 2016; server = false; copyOnRead = false; lockLease = 120;
lockTimeout = 60]: Now closing.
[info 2016/08/11 15:55:58.143 PDT <Test worker> tid=0xa] Cache server on port
48,141 is shutting down.
[info 2016/08/11 15:55:58.144 PDT <Queue Removal Thread> tid=0x150] The
QueueRemovalThread is done.
[vm_1][info 2016/08/11 15:55:58.148 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/2030275699.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/2030275699@9ac4e43
[vm_1][info 2016/08/11 15:55:58.148 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/2030275699.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/2030275699@9ac4e43
(took 0 ms)
[vm_2][info 2016/08/11 15:55:58.148 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/594604168.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/594604168@36da73a7
[vm_2][info 2016/08/11 15:55:58.149 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/594604168.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$19/594604168@36da73a7
(took 0 ms)
[vm_3][info 2016/08/11 15:55:58.149 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$18/1252408301.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$18/1252408301@2f849c33
[vm_3][info 2016/08/11 15:55:58.149 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$18/1252408301.run
with 0 args on object:
com.gemstone.gemfire.test.dunit.cache.internal.JUnit4CacheTestCase$$Lambda$18/1252408301@2f849c33
(took 0 ms)
[vm_1][info 2016/08/11 15:55:58.151 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownCreationStackGenerator)
[vm_1][info 2016/08/11 15:55:58.151 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownCreationStackGenerator) (took 0 ms)
[vm_2][info 2016/08/11 15:55:58.152 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownCreationStackGenerator)
[vm_2][info 2016/08/11 15:55:58.152 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownCreationStackGenerator) (took 0 ms)
[vm_3][info 2016/08/11 15:55:58.152 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownCreationStackGenerator)
[vm_3][info 2016/08/11 15:55:58.152 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownCreationStackGenerator) (took 0 ms)
[vm_1][info 2016/08/11 15:55:58.155 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownVM)
[vm_1][info 2016/08/11 15:55:58.155 PDT <RMI TCP Connection(1)-10.118.32.90>
tid=0x12] Got result: null
[vm_1] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownVM) (took 0 ms)
[vm_2][info 2016/08/11 15:55:58.155 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownVM)
[vm_2][info 2016/08/11 15:55:58.155 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_2] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownVM) (took 0 ms)
[vm_3][info 2016/08/11 15:55:58.156 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Received method: com.gemstone.gemfire.test.dunit.NamedRunnable.run
with 0 args on object: runnable(tearDownVM)
[vm_3][info 2016/08/11 15:55:58.156 PDT <RMI TCP Connection(45)-10.118.32.90>
tid=0x12] Got result: null
[vm_3] from com.gemstone.gemfire.test.dunit.NamedRunnable.run with 0 args on
object: runnable(tearDownVM) (took 0 ms)
Standard error
Suspicious strings were written to the log during this run.
Fix the strings or use IgnoredException.addIgnoredException to ignore.
-----------------------------------------------------------------------
Found suspect string in log4j at line 91
[fatal 2016/08/11 15:55:58.089 PDT <JMX client heartbeat 2> tid=0xae] (tid=174
msgId=10) No longer connected to localhost[20406].
Generated by Gradle 2.14.1 at Aug 11, 2016 7:31:10 PM
> CI failure:
> IntegratedClientRegisterInterestAuthDistributedTest.testRegisterInterest
> ------------------------------------------------------------------------------------
>
> Key: GEODE-1769
> URL: https://issues.apache.org/jira/browse/GEODE-1769
> Project: Geode
> Issue Type: Bug
> Components: security
> Reporter: Hitesh Khamesra
> Labels: CI
>
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
