You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2018/01/06 13:03:18 UTC
[JENKINS] Lucene-Solr-master-Linux (32bit/jdk1.8.0_144) - Build #
21225 - Unstable!
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-master-Linux/21225/
Java: 32bit/jdk1.8.0_144 -client -XX:+UseConcMarkSweepGC
1 tests failed.
FAILED: junit.framework.TestSuite.org.apache.solr.cloud.TestSolrCloudWithSecureImpersonation
Error Message:
1 thread leaked from SUITE scope at org.apache.solr.cloud.TestSolrCloudWithSecureImpersonation: 1) Thread[id=2062, name=jetty-launcher-520-thread-1-EventThread, state=TIMED_WAITING, group=TGRP-TestSolrCloudWithSecureImpersonation] at sun.misc.Unsafe.park(Native Method) at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215) at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037) at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328) at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277) at org.apache.curator.CuratorZookeeperClient.internalBlockUntilConnectedOrTimedOut(CuratorZookeeperClient.java:323) at org.apache.curator.RetryLoop.callWithRetry(RetryLoop.java:105) at org.apache.curator.framework.imps.GetDataBuilderImpl.pathInForeground(GetDataBuilderImpl.java:288) at org.apache.curator.framework.imps.GetDataBuilderImpl.forPath(GetDataBuilderImpl.java:279) at org.apache.curator.framework.imps.GetDataBuilderImpl.forPath(GetDataBuilderImpl.java:41) at org.apache.curator.framework.recipes.shared.SharedValue.readValue(SharedValue.java:244) at org.apache.curator.framework.recipes.shared.SharedValue.access$100(SharedValue.java:44) at org.apache.curator.framework.recipes.shared.SharedValue$1.process(SharedValue.java:61) at org.apache.curator.framework.imps.NamespaceWatcher.process(NamespaceWatcher.java:67) at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:530) at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:505)
Stack Trace:
com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.cloud.TestSolrCloudWithSecureImpersonation:
1) Thread[id=2062, name=jetty-launcher-520-thread-1-EventThread, state=TIMED_WAITING, group=TGRP-TestSolrCloudWithSecureImpersonation]
at sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277)
at org.apache.curator.CuratorZookeeperClient.internalBlockUntilConnectedOrTimedOut(CuratorZookeeperClient.java:323)
at org.apache.curator.RetryLoop.callWithRetry(RetryLoop.java:105)
at org.apache.curator.framework.imps.GetDataBuilderImpl.pathInForeground(GetDataBuilderImpl.java:288)
at org.apache.curator.framework.imps.GetDataBuilderImpl.forPath(GetDataBuilderImpl.java:279)
at org.apache.curator.framework.imps.GetDataBuilderImpl.forPath(GetDataBuilderImpl.java:41)
at org.apache.curator.framework.recipes.shared.SharedValue.readValue(SharedValue.java:244)
at org.apache.curator.framework.recipes.shared.SharedValue.access$100(SharedValue.java:44)
at org.apache.curator.framework.recipes.shared.SharedValue$1.process(SharedValue.java:61)
at org.apache.curator.framework.imps.NamespaceWatcher.process(NamespaceWatcher.java:67)
at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:530)
at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:505)
at __randomizedtesting.SeedInfo.seed([2437EAE19FD1F665]:0)
Build Log:
[...truncated 11851 lines...]
[junit4] Suite: org.apache.solr.cloud.TestSolrCloudWithSecureImpersonation
[junit4] 2> 214207 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[2437EAE19FD1F665]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.TestSolrCloudWithSecureImpersonation_2437EAE19FD1F665-001/init-core-data-001
[junit4] 2> 214208 WARN (SUITE-TestSolrCloudWithSecureImpersonation-seed#[2437EAE19FD1F665]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=10 numCloses=10
[junit4] 2> 214208 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[2437EAE19FD1F665]-worker) [ ] o.a.s.SolrTestCaseJ4 Using TrieFields (NUMERIC_POINTS_SYSPROP=false) w/NUMERIC_DOCVALUES_SYSPROP=false
[junit4] 2> 214209 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[2437EAE19FD1F665]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (false) and clientAuth (true) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN)
[junit4] 2> 214267 WARN (SUITE-TestSolrCloudWithSecureImpersonation-seed#[2437EAE19FD1F665]-worker) [ ] o.a.h.u.NativeCodeLoader Unable to load native-hadoop library for your platform... using builtin-java classes where applicable
[junit4] 2> 214365 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[2437EAE19FD1F665]-worker) [ ] o.a.s.c.MiniSolrCloudCluster Starting cluster of 2 servers in /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.TestSolrCloudWithSecureImpersonation_2437EAE19FD1F665-001/tempDir-001
[junit4] 2> 214365 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[2437EAE19FD1F665]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER
[junit4] 2> 214366 INFO (Thread-302) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 214366 INFO (Thread-302) [ ] o.a.s.c.ZkTestServer Starting server
[junit4] 2> 214367 ERROR (Thread-302) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes
[junit4] 2> 214466 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[2437EAE19FD1F665]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:38183
[junit4] 2> 214468 INFO (zkConnectionManagerCallback-523-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 214471 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x160cb5cfbd30000, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 214472 INFO (jetty-launcher-520-thread-2) [ ] o.e.j.s.Server jetty-9.3.20.v20170531
[junit4] 2> 214472 INFO (jetty-launcher-520-thread-1) [ ] o.e.j.s.Server jetty-9.3.20.v20170531
[junit4] 2> 214473 INFO (jetty-launcher-520-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@3a574{/solr,null,AVAILABLE}
[junit4] 2> 214473 INFO (jetty-launcher-520-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@c410d7{/solr,null,AVAILABLE}
[junit4] 2> 214475 INFO (jetty-launcher-520-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@d98b6{HTTP/1.1,[http/1.1]}{127.0.0.1:43967}
[junit4] 2> 214475 INFO (jetty-launcher-520-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@170669c{HTTP/1.1,[http/1.1]}{127.0.0.1:37169}
[junit4] 2> 214475 INFO (jetty-launcher-520-thread-2) [ ] o.e.j.s.Server Started @215412ms
[junit4] 2> 214475 INFO (jetty-launcher-520-thread-1) [ ] o.e.j.s.Server Started @215413ms
[junit4] 2> 214475 INFO (jetty-launcher-520-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=43967}
[junit4] 2> 214475 INFO (jetty-launcher-520-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=37169}
[junit4] 2> 214476 ERROR (jetty-launcher-520-thread-2) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 214476 ERROR (jetty-launcher-520-thread-1) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete.
[junit4] 2> 214476 INFO (jetty-launcher-520-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 8.0.0
[junit4] 2> 214476 INFO (jetty-launcher-520-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 8.0.0
[junit4] 2> 214476 INFO (jetty-launcher-520-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 214476 INFO (jetty-launcher-520-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null
[junit4] 2> 214476 INFO (jetty-launcher-520-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 214476 INFO (jetty-launcher-520-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null
[junit4] 2> 214476 INFO (jetty-launcher-520-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-01-06T12:05:56.928Z
[junit4] 2> 214476 INFO (jetty-launcher-520-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-01-06T12:05:56.928Z
[junit4] 2> 214477 INFO (zkConnectionManagerCallback-525-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 214478 INFO (zkConnectionManagerCallback-527-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 214478 INFO (jetty-launcher-520-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 214479 INFO (jetty-launcher-520-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading...
[junit4] 2> 214505 INFO (jetty-launcher-520-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:38183/solr
[junit4] 2> 214508 INFO (jetty-launcher-520-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:38183/solr
[junit4] 2> 214512 INFO (zkConnectionManagerCallback-532-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 214514 INFO (zkConnectionManagerCallback-535-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 214515 INFO (zkConnectionManagerCallback-537-thread-1-processing-n:127.0.0.1:37169_solr) [n:127.0.0.1:37169_solr ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 214518 INFO (zkConnectionManagerCallback-539-thread-1-processing-n:127.0.0.1:43967_solr) [n:127.0.0.1:43967_solr ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 214587 INFO (jetty-launcher-520-thread-1) [n:127.0.0.1:37169_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 214587 INFO (jetty-launcher-520-thread-1) [n:127.0.0.1:37169_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:37169_solr
[junit4] 2> 214588 INFO (jetty-launcher-520-thread-1) [n:127.0.0.1:37169_solr ] o.a.s.c.Overseer Overseer (id=99302792024489989-127.0.0.1:37169_solr-n_0000000000) starting
[junit4] 2> 214590 INFO (jetty-launcher-520-thread-2) [n:127.0.0.1:43967_solr ] o.a.s.c.Overseer Overseer (id=null) closing
[junit4] 2> 214591 INFO (jetty-launcher-520-thread-2) [n:127.0.0.1:43967_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:43967_solr
[junit4] 2> 214592 INFO (zkCallback-538-thread-1-processing-n:127.0.0.1:43967_solr) [n:127.0.0.1:43967_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 214593 INFO (OverseerStateUpdate-99302792024489989-127.0.0.1:37169_solr-n_0000000000) [n:127.0.0.1:37169_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1)
[junit4] 2> 214593 INFO (jetty-launcher-520-thread-1) [n:127.0.0.1:37169_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37169_solr
[junit4] 2> 214596 INFO (zkCallback-538-thread-1-processing-n:127.0.0.1:43967_solr) [n:127.0.0.1:43967_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 214596 INFO (zkCallback-536-thread-1-processing-n:127.0.0.1:37169_solr) [n:127.0.0.1:37169_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2)
[junit4] 2> 214670 INFO (jetty-launcher-520-thread-1) [n:127.0.0.1:37169_solr ] o.a.s.c.CoreContainer Initializing authentication plugin: org.apache.solr.security.HttpParamDelegationTokenPlugin
[junit4] 2> 214675 WARN (jetty-launcher-520-thread-1) [n:127.0.0.1:37169_solr ] o.a.s.c.s.i.Krb5HttpClientBuilder org.apache.solr.client.solrj.impl.Krb5HttpClientBuilder is configured without specifying system property 'java.security.auth.login.config'
[junit4] 2> 214688 INFO (jetty-launcher-520-thread-2) [n:127.0.0.1:43967_solr ] o.a.s.c.CoreContainer Initializing authentication plugin: org.apache.solr.security.HttpParamDelegationTokenPlugin
[junit4] 2> 214688 WARN (jetty-launcher-520-thread-2) [n:127.0.0.1:43967_solr ] o.a.s.c.s.i.Krb5HttpClientBuilder org.apache.solr.client.solrj.impl.Krb5HttpClientBuilder is configured without specifying system property 'java.security.auth.login.config'
[junit4] 2> 214693 INFO (jetty-launcher-520-thread-1) [n:127.0.0.1:37169_solr ] o.a.s.s.KerberosPlugin Params: {solr.kerberos.impersonator.user.noGroups.hosts=*, solr.kerberos.impersonator.user.bogusGroup.groups=__some_bogus_group, token.valid=30, cookie.domain=127.0.0.1, solr.kerberos.impersonator.user.anyHostAnyUser.groups=*, solr.kerberos.impersonator.user.bogusGroup.hosts=*, solr.kerberos.impersonator.user.anyHostAnyUser.hosts=*, token.validity=36000, solr.kerberos.impersonator.user.noHosts.groups=*, type=kerberos, solr.kerberos.impersonator.user.localHostAnyGroup.groups=*, delegation-token.token-kind=solr-dt, solr.kerberos.impersonator.user.wrongHost.hosts=1.1.1.1.1.1, cookie.path=/, zk-dt-secret-manager.znodeWorkingPath=solr/security/zkdtsm, solr.kerberos.impersonator.user.localHostAnyGroup.hosts=localhost.localdomain,localhost,127.0.0.1, signer.secret.provider.zookeeper.path=/token, solr.kerberos.impersonator.user.anyHostUsersGroup.groups=jenkins, zk-dt-secret-manager.enable=true, solr.kerberos.impersonator.user.wrongHost.groups=*, kerberos.name.rules=DEFAULT, signer.secret.provider=zookeeper, solr.kerberos.impersonator.user.anyHostUsersGroup.hosts=*}
[junit4] 2> 214693 INFO (jetty-launcher-520-thread-2) [n:127.0.0.1:43967_solr ] o.a.s.s.KerberosPlugin Params: {solr.kerberos.impersonator.user.noGroups.hosts=*, solr.kerberos.impersonator.user.bogusGroup.groups=__some_bogus_group, token.valid=30, cookie.domain=127.0.0.1, solr.kerberos.impersonator.user.anyHostAnyUser.groups=*, solr.kerberos.impersonator.user.bogusGroup.hosts=*, solr.kerberos.impersonator.user.anyHostAnyUser.hosts=*, token.validity=36000, solr.kerberos.impersonator.user.noHosts.groups=*, type=kerberos, solr.kerberos.impersonator.user.localHostAnyGroup.groups=*, delegation-token.token-kind=solr-dt, solr.kerberos.impersonator.user.wrongHost.hosts=1.1.1.1.1.1, cookie.path=/, zk-dt-secret-manager.znodeWorkingPath=solr/security/zkdtsm, solr.kerberos.impersonator.user.localHostAnyGroup.hosts=localhost.localdomain,localhost,127.0.0.1, signer.secret.provider.zookeeper.path=/token, solr.kerberos.impersonator.user.anyHostUsersGroup.groups=jenkins, zk-dt-secret-manager.enable=true, solr.kerberos.impersonator.user.wrongHost.groups=*, kerberos.name.rules=DEFAULT, signer.secret.provider=zookeeper, solr.kerberos.impersonator.user.anyHostUsersGroup.hosts=*}
[junit4] 2> 214785 INFO (jetty-launcher-520-thread-2) [n:127.0.0.1:43967_solr ] o.a.c.f.i.CuratorFrameworkImpl Starting
[junit4] 2> 214785 INFO (jetty-launcher-520-thread-1) [n:127.0.0.1:37169_solr ] o.a.c.f.i.CuratorFrameworkImpl Starting
[junit4] 2> 214821 INFO (jetty-launcher-520-thread-2-EventThread) [n:127.0.0.1:43967_solr ] o.a.c.f.s.ConnectionStateManager State change: CONNECTED
[junit4] 2> 214821 INFO (jetty-launcher-520-thread-1-EventThread) [n:127.0.0.1:37169_solr ] o.a.c.f.s.ConnectionStateManager State change: CONNECTED
[junit4] 2> 214971 WARN (jetty-launcher-520-thread-2) [n:127.0.0.1:43967_solr ] o.a.s.c.s.i.Krb5HttpClientBuilder org.apache.solr.client.solrj.impl.Krb5HttpClientBuilder is configured without specifying system property 'java.security.auth.login.config'
[junit4] 2> 214971 WARN (jetty-launcher-520-thread-1) [n:127.0.0.1:37169_solr ] o.a.s.c.s.i.Krb5HttpClientBuilder org.apache.solr.client.solrj.impl.Krb5HttpClientBuilder is configured without specifying system property 'java.security.auth.login.config'
[junit4] 2> 215069 INFO (jetty-launcher-520-thread-2) [n:127.0.0.1:43967_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_43967.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@1a9e5c0
[junit4] 2> 215074 INFO (jetty-launcher-520-thread-1) [n:127.0.0.1:37169_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_37169.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@1a9e5c0
[junit4] 2> 215120 INFO (jetty-launcher-520-thread-1) [n:127.0.0.1:37169_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_37169.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@1a9e5c0
[junit4] 2> 215121 INFO (jetty-launcher-520-thread-1) [n:127.0.0.1:37169_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_37169.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@1a9e5c0
[junit4] 2> 215126 INFO (jetty-launcher-520-thread-1) [n:127.0.0.1:37169_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.TestSolrCloudWithSecureImpersonation_2437EAE19FD1F665-001/tempDir-001/node1/.
[junit4] 2> 215144 INFO (jetty-launcher-520-thread-2) [n:127.0.0.1:43967_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_43967.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@1a9e5c0
[junit4] 2> 215145 INFO (jetty-launcher-520-thread-2) [n:127.0.0.1:43967_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_43967.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@1a9e5c0
[junit4] 2> 215147 INFO (jetty-launcher-520-thread-2) [n:127.0.0.1:43967_solr ] o.a.s.c.CorePropertiesLocator Found 0 core definitions underneath /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.TestSolrCloudWithSecureImpersonation_2437EAE19FD1F665-001/tempDir-001/node2/.
[junit4] 2> 215280 INFO (zkConnectionManagerCallback-545-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 215294 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidGroup-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyInvalidGroup
[junit4] 2> 215351 WARN (qtp22995269-2010) [ ] o.a.h.s.ShellBasedUnixGroupsMapping got exception trying to get groups for user bar: id: ???bar???: no such user
[junit4] 2> id: ???bar???: no such user
[junit4] 2>
[junit4] 2> 215670 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidGroup-seed#[2437EAE19FD1F665]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=bogusGroup&p=bogusGroup&t=test&e=1515276357761&s=W0vE14VApd4L5JtoDjXW4SqAj8I="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:05:57 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:05:57 GMT
[junit4] 2> 215671 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidGroup-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyInvalidGroup
[junit4] 2> 215682 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateHost-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyValidateHost
[junit4] 2> 215688 INFO (qtp22995269-2022) [n:127.0.0.1:37169_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params doAs=bar&action=LIST&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 215688 INFO (qtp22995269-2022) [n:127.0.0.1:37169_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={doAs=bar&action=LIST&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 215690 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateHost-seed#[2437EAE19FD1F665]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=localHostAnyGroup&p=localHostAnyGroup&t=test&e=1515276358135&s=B+z9/V7URhSBp/IKSY4wysd6ixE="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:05:58 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:05:58 GMT
[junit4] 2> 215690 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateHost-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyValidateHost
[junit4] 2> 215704 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyNoConfigHosts-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyNoConfigHosts
[junit4] 2> 215710 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyNoConfigHosts-seed#[2437EAE19FD1F665]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=noHosts&p=noHosts&t=test&e=1515276358157&s=tDvQvnWuzgVnRp4SGQwCc5EGB3w="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:05:58 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:05:58 GMT
[junit4] 2> 215710 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyNoConfigHosts-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyNoConfigHosts
[junit4] 2> 215731 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateAnyHostAnyUser-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyValidateAnyHostAnyUser
[junit4] 2> 215732 INFO (qtp22995269-2020) [n:127.0.0.1:37169_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params doAs=bar&action=LIST&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 215732 INFO (qtp22995269-2020) [n:127.0.0.1:37169_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={doAs=bar&action=LIST&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 215733 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateAnyHostAnyUser-seed#[2437EAE19FD1F665]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=anyHostAnyUser&p=anyHostAnyUser&t=test&e=1515276358184&s=FfBpBmtDHN7SZGprUgQhayCJW2I="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:05:58 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:05:58 GMT
[junit4] 2> 215733 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateAnyHostAnyUser-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyValidateAnyHostAnyUser
[junit4] 2> 215743 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidProxyUser-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyInvalidProxyUser
[junit4] 2> 215746 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidProxyUser-seed#[2437EAE19FD1F665]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=bar&p=bar&t=test&e=1515276358196&s=GqfoYMW5+Vr4Y0006LFZbtfkEp4="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:05:58 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:05:58 GMT
[junit4] 2> 215746 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidProxyUser-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyInvalidProxyUser
[junit4] 2> 215756 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyNullProxyUser-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyNullProxyUser
[junit4] 2> 215757 INFO (qtp22995269-2022) [n:127.0.0.1:37169_solr ] o.a.s.s.SolrDispatchFilter Error authenticating
[junit4] 2> java.lang.IllegalArgumentException: userName is NULL, empty or contains a '&'
[junit4] 2> at org.apache.hadoop.security.authentication.util.AuthToken.checkForIllegalArgument(AuthToken.java:87)
[junit4] 2> at org.apache.hadoop.security.authentication.util.AuthToken.<init>(AuthToken.java:70)
[junit4] 2> at org.apache.hadoop.security.authentication.server.AuthenticationToken.<init>(AuthenticationToken.java:58)
[junit4] 2> at org.apache.solr.security.HttpParamDelegationTokenPlugin$HttpParamDelegationTokenAuthenticationHandler$HttpParamAuthenticationHandler.authenticate(HttpParamDelegationTokenPlugin.java:213)
[junit4] 2> at org.apache.hadoop.security.token.delegation.web.DelegationTokenAuthenticationHandler.authenticate(DelegationTokenAuthenticationHandler.java:348)
[junit4] 2> at org.apache.solr.security.RequestContinuesRecorderAuthenticationHandler.authenticate(RequestContinuesRecorderAuthenticationHandler.java:69)
[junit4] 2> at org.apache.hadoop.security.authentication.server.AuthenticationFilter.doFilter(AuthenticationFilter.java:518)
[junit4] 2> at org.apache.solr.security.DelegationTokenKerberosFilter.doFilter(DelegationTokenKerberosFilter.java:134)
[junit4] 2> at org.apache.solr.security.HttpParamDelegationTokenPlugin$HttpParamToRequestFilter.doFilter(HttpParamDelegationTokenPlugin.java:245)
[junit4] 2> at org.apache.solr.security.KerberosPlugin.doAuthenticate(KerberosPlugin.java:243)
[junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.authenticateRequest(SolrDispatchFilter.java:451)
[junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:347)
[junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:326)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759)
[junit4] 2> at org.apache.solr.client.solrj.embedded.JettySolrRunner$DebugFilter.doFilter(JettySolrRunner.java:139)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:582)
[junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:224)
[junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512)
[junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
[junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112)
[junit4] 2> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
[junit4] 2> at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:493)
[junit4] 2> at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
[junit4] 2> at org.eclipse.jetty.server.Server.handle(Server.java:534)
[junit4] 2> at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320)
[junit4] 2> at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
[junit4] 2> at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283)
[junit4] 2> at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108)
[junit4] 2> at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
[junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
[junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
[junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 215758 WARN (qtp22995269-2022) [n:127.0.0.1:37169_solr ] o.e.j.s.ServletHandler /solr/admin/collections
[junit4] 2> org.apache.solr.common.SolrException: Error during request authentication,
[junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.authenticateRequest(SolrDispatchFilter.java:457)
[junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:347)
[junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:326)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759)
[junit4] 2> at org.apache.solr.client.solrj.embedded.JettySolrRunner$DebugFilter.doFilter(JettySolrRunner.java:139)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1759)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:582)
[junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:224)
[junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1180)
[junit4] 2> at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:512)
[junit4] 2> at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:185)
[junit4] 2> at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1112)
[junit4] 2> at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:141)
[junit4] 2> at org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:493)
[junit4] 2> at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:134)
[junit4] 2> at org.eclipse.jetty.server.Server.handle(Server.java:534)
[junit4] 2> at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:320)
[junit4] 2> at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
[junit4] 2> at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:283)
[junit4] 2> at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:108)
[junit4] 2> at org.eclipse.jetty.io.SelectChannelEndPoint$2.run(SelectChannelEndPoint.java:93)
[junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.executeProduceConsume(ExecuteProduceConsume.java:303)
[junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.produceConsume(ExecuteProduceConsume.java:148)
[junit4] 2> at org.eclipse.jetty.util.thread.strategy.ExecuteProduceConsume.run(ExecuteProduceConsume.java:136)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:671)
[junit4] 2> at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:589)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> Caused by: java.lang.IllegalArgumentException: userName is NULL, empty or contains a '&'
[junit4] 2> at org.apache.hadoop.security.authentication.util.AuthToken.checkForIllegalArgument(AuthToken.java:87)
[junit4] 2> at org.apache.hadoop.security.authentication.util.AuthToken.<init>(AuthToken.java:70)
[junit4] 2> at org.apache.hadoop.security.authentication.server.AuthenticationToken.<init>(AuthenticationToken.java:58)
[junit4] 2> at org.apache.solr.security.HttpParamDelegationTokenPlugin$HttpParamDelegationTokenAuthenticationHandler$HttpParamAuthenticationHandler.authenticate(HttpParamDelegationTokenPlugin.java:213)
[junit4] 2> at org.apache.hadoop.security.token.delegation.web.DelegationTokenAuthenticationHandler.authenticate(DelegationTokenAuthenticationHandler.java:348)
[junit4] 2> at org.apache.solr.security.RequestContinuesRecorderAuthenticationHandler.authenticate(RequestContinuesRecorderAuthenticationHandler.java:69)
[junit4] 2> at org.apache.hadoop.security.authentication.server.AuthenticationFilter.doFilter(AuthenticationFilter.java:518)
[junit4] 2> at org.apache.solr.security.DelegationTokenKerberosFilter.doFilter(DelegationTokenKerberosFilter.java:134)
[junit4] 2> at org.apache.solr.security.HttpParamDelegationTokenPlugin$HttpParamToRequestFilter.doFilter(HttpParamDelegationTokenPlugin.java:245)
[junit4] 2> at org.apache.solr.security.KerberosPlugin.doAuthenticate(KerberosPlugin.java:243)
[junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.authenticateRequest(SolrDispatchFilter.java:451)
[junit4] 2> ... 26 more
[junit4] 2> 215761 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyNullProxyUser-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyNullProxyUser
[junit4] 2> 215771 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyWrongHost-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyWrongHost
[junit4] 2> 225888 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyWrongHost-seed#[2437EAE19FD1F665]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=wrongHost&p=wrongHost&t=test&e=1515276358226&s=tVJP91nMtiznQn/QtfhJ2G5zj4g="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:05:58 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:05:58 GMT
[junit4] 2> 225888 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyWrongHost-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyWrongHost
[junit4] 2> 225902 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyNoConfigGroups-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyNoConfigGroups
[junit4] 2> 225906 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyNoConfigGroups-seed#[2437EAE19FD1F665]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=noGroups&p=noGroups&t=test&e=1515276368355&s=v5msEOTFpLgEMlOPCGFEUCnbNPo="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:06:08 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:06:08 GMT
[junit4] 2> 225906 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyNoConfigGroups-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyNoConfigGroups
[junit4] 2> 225920 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidRemote-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyInvalidRemote
[junit4] 2> 225927 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidRemote-seed#[2437EAE19FD1F665]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=localHostAnyGroup&p=localHostAnyGroup&t=test&e=1515276368372&s=aMhA4IJtMYfs+RbLv/lsiRjvPtI="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:06:08 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:06:08 GMT
[junit4] 2> 225927 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidRemote-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyInvalidRemote
[junit4] 2> 225939 INFO (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testForwarding
[junit4] 2> 225941 INFO (zkConnectionManagerCallback-548-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 226161 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x160cb5cfbd3000a, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 226165 INFO (zkConnectionManagerCallback-551-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected
[junit4] 2> 226166 INFO (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[2437EAE19FD1F665]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2)
[junit4] 2> 226166 INFO (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[2437EAE19FD1F665]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:38183/solr ready
[junit4] 2> 226169 INFO (qtp19444460-2019) [n:127.0.0.1:43967_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :create with params pullReplicas=0&replicationFactor=1&collection.configName=conf1&maxShardsPerNode=1&name=forwardingCollection&nrtReplicas=1&action=CREATE&numShards=1&tlogReplicas=0&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 226170 INFO (OverseerThreadFactory-708-thread-1-processing-n:127.0.0.1:37169_solr) [n:127.0.0.1:37169_solr ] o.a.s.c.CreateCollectionCmd Create collection forwardingCollection
[junit4] 2> 226279 INFO (OverseerStateUpdate-99302792024489989-127.0.0.1:37169_solr-n_0000000000) [n:127.0.0.1:37169_solr ] o.a.s.c.o.SliceMutator createReplica() {
[junit4] 2> "operation":"ADDREPLICA",
[junit4] 2> "collection":"forwardingCollection",
[junit4] 2> "shard":"shard1",
[junit4] 2> "core":"forwardingCollection_shard1_replica_n1",
[junit4] 2> "state":"down",
[junit4] 2> "base_url":"http://127.0.0.1:37169/solr",
[junit4] 2> "type":"NRT",
[junit4] 2> "waitForFinalState":"false"}
[junit4] 2> 226482 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr ] o.a.s.h.a.CoreAdminOperation core create command qt=/admin/cores&coreNodeName=core_node2&collection.configName=conf1&newCollection=true&name=forwardingCollection_shard1_replica_n1&action=CREATE&numShards=1&collection=forwardingCollection&shard=shard1&wt=javabin&version=2&replicaType=NRT
[junit4] 2> 226483 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 226586 INFO (zkCallback-536-thread-1-processing-n:127.0.0.1:37169_solr) [n:127.0.0.1:37169_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forwardingCollection/state.json] for collection [forwardingCollection] has occurred - updating... (live nodes size: [2])
[junit4] 2> 226587 INFO (zkCallback-536-thread-2-processing-n:127.0.0.1:37169_solr) [n:127.0.0.1:37169_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forwardingCollection/state.json] for collection [forwardingCollection] has occurred - updating... (live nodes size: [2])
[junit4] 2> 227522 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.SolrConfig Using Lucene MatchVersion: 8.0.0
[junit4] 2> 227574 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.s.IndexSchema [forwardingCollection_shard1_replica_n1] Schema name=test
[junit4] 2> 227804 WARN (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.SolrResourceLoader Solr loaded a deprecated plugin/analysis class [solr.EnumField]. Please consult documentation how to replace it accordingly.
[junit4] 2> 227829 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.s.IndexSchema Loaded schema test/1.0 with uniqueid field id
[junit4] 2> 227865 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.CoreContainer Creating SolrCore 'forwardingCollection_shard1_replica_n1' using configuration from collection forwardingCollection, trusted=true
[junit4] 2> 227866 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_37169.solr.core.forwardingCollection.shard1.replica_n1' (registry 'solr.core.forwardingCollection.shard1.replica_n1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@1a9e5c0
[junit4] 2> 227866 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder
[junit4] 2> 227866 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.SolrCore [[forwardingCollection_shard1_replica_n1] ] Opening new SolrCore at [/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.TestSolrCloudWithSecureImpersonation_2437EAE19FD1F665-001/tempDir-001/node1/forwardingCollection_shard1_replica_n1], dataDir=[/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.TestSolrCloudWithSecureImpersonation_2437EAE19FD1F665-001/tempDir-001/node1/./forwardingCollection_shard1_replica_n1/data/]
[junit4] 2> 227872 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=17, maxMergeAtOnceExplicit=20, maxMergedSegmentMB=2.1083984375, floorSegmentMB=0.43359375, forceMergeDeletesPctAllowed=22.506846793690602, segmentsPerTier=47.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.2993080931878178
[junit4] 2> 227996 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.u.UpdateHandler Using UpdateLog implementation: org.apache.solr.update.UpdateLog
[junit4] 2> 227996 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.u.UpdateLog Initializing UpdateLog: dataDir= defaultSyncLevel=FLUSH numRecordsToKeep=100 maxNumLogsToKeep=10 numVersionBuckets=65536
[junit4] 2> 227998 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.u.CommitTracker Hard AutoCommit: disabled
[junit4] 2> 227998 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.u.CommitTracker Soft AutoCommit: disabled
[junit4] 2> 228000 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.u.RandomMergePolicy RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=30, maxMergeAtOnceExplicit=37, maxMergedSegmentMB=68.701171875, floorSegmentMB=0.677734375, forceMergeDeletesPctAllowed=7.674510860292166, segmentsPerTier=37.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.8756573439796872
[junit4] 2> 228000 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@1e8ef6e[forwardingCollection_shard1_replica_n1] main]
[junit4] 2> 228003 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.h.c.SpellCheckComponent Initializing spell checkers
[junit4] 2> 228044 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.s.DirectSolrSpellChecker init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4] 2> 228133 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
[junit4] 2> 228133 INFO (searcherExecutor-713-thread-1-processing-n:127.0.0.1:37169_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: default
[junit4] 2> 228133 INFO (searcherExecutor-713-thread-1-processing-n:127.0.0.1:37169_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: direct
[junit4] 2> 228133 INFO (searcherExecutor-713-thread-1-processing-n:127.0.0.1:37169_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: wordbreak
[junit4] 2> 228134 INFO (searcherExecutor-713-thread-1-processing-n:127.0.0.1:37169_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: multipleFields
[junit4] 2> 228134 INFO (searcherExecutor-713-thread-1-processing-n:127.0.0.1:37169_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: jarowinkler
[junit4] 2> 228134 INFO (searcherExecutor-713-thread-1-processing-n:127.0.0.1:37169_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: external
[junit4] 2> 228134 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.u.UpdateLog Could not find max version in index or recent updates, using new clock 1588844686827585536
[junit4] 2> 228134 INFO (searcherExecutor-713-thread-1-processing-n:127.0.0.1:37169_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: freq
[junit4] 2> 228135 INFO (searcherExecutor-713-thread-1-processing-n:127.0.0.1:37169_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: fqcn
[junit4] 2> 228135 INFO (searcherExecutor-713-thread-1-processing-n:127.0.0.1:37169_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.h.c.SpellCheckComponent Loading spell index for spellchecker: perDict
[junit4] 2> 228137 INFO (searcherExecutor-713-thread-1-processing-n:127.0.0.1:37169_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.SolrCore [forwardingCollection_shard1_replica_n1] Registered new searcher Searcher@1e8ef6e[forwardingCollection_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 228139 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext Enough replicas found to continue.
[junit4] 2> 228139 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext I may be the new leader - try and sync
[junit4] 2> 228139 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.SyncStrategy Sync replicas to http://127.0.0.1:37169/solr/forwardingCollection_shard1_replica_n1/
[junit4] 2> 228140 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.SyncStrategy Sync Success - now sync replicas to me
[junit4] 2> 228140 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.SyncStrategy http://127.0.0.1:37169/solr/forwardingCollection_shard1_replica_n1/ has no replicas
[junit4] 2> 228140 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext Found all replicas participating in election, clear LIR
[junit4] 2> 228142 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext I am the new leader: http://127.0.0.1:37169/solr/forwardingCollection_shard1_replica_n1/ shard1
[junit4] 2> 228246 INFO (zkCallback-536-thread-3-processing-n:127.0.0.1:37169_solr) [n:127.0.0.1:37169_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forwardingCollection/state.json] for collection [forwardingCollection] has occurred - updating... (live nodes size: [2])
[junit4] 2> 228246 INFO (zkCallback-536-thread-2-processing-n:127.0.0.1:37169_solr) [n:127.0.0.1:37169_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forwardingCollection/state.json] for collection [forwardingCollection] has occurred - updating... (live nodes size: [2])
[junit4] 2> 228296 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.ZkController I am the leader, no recovery necessary
[junit4] 2> 228298 INFO (qtp22995269-2010) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/cores params={qt=/admin/cores&coreNodeName=core_node2&collection.configName=conf1&newCollection=true&name=forwardingCollection_shard1_replica_n1&action=CREATE&numShards=1&collection=forwardingCollection&shard=shard1&wt=javabin&version=2&replicaType=NRT} status=0 QTime=1816
[junit4] 2> 228299 WARN (httpShardExecutor-700-thread-1-processing-n:127.0.0.1:37169_solr [http:////127.0.0.1:37169//solr] http:////127.0.0.1:37169//solr) [n:127.0.0.1:37169_solr ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=$&p=$&t=test&e=1515276368934&s=SoeRYfhvEUkl01Lwe6p6uQy36qk="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:06:08 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:06:08 GMT
[junit4] 2> 228302 INFO (qtp19444460-2019) [n:127.0.0.1:43967_solr ] o.a.s.h.a.CollectionsHandler Wait for new collection to be active for at most 30 seconds. Check all shard replicas
[junit4] 2> 228399 INFO (zkCallback-536-thread-2-processing-n:127.0.0.1:37169_solr) [n:127.0.0.1:37169_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forwardingCollection/state.json] for collection [forwardingCollection] has occurred - updating... (live nodes size: [2])
[junit4] 2> 228399 INFO (zkCallback-536-thread-3-processing-n:127.0.0.1:37169_solr) [n:127.0.0.1:37169_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forwardingCollection/state.json] for collection [forwardingCollection] has occurred - updating... (live nodes size: [2])
[junit4] 2> 229303 INFO (qtp19444460-2019) [n:127.0.0.1:43967_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={pullReplicas=0&replicationFactor=1&collection.configName=conf1&maxShardsPerNode=1&name=forwardingCollection&nrtReplicas=1&action=CREATE&numShards=1&tlogReplicas=0&wt=javabin&version=2} status=0 QTime=3134
[junit4] 2> 229304 WARN (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[2437EAE19FD1F665]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=user&p=user&t=test&e=1515276368620&s=49i2i3eDOI3Brx7wrztUa/r8ADA="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:06:08 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:06:08 GMT
[junit4] 2> 229304 INFO (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[2437EAE19FD1F665]) [ ] o.a.s.c.AbstractDistribZkTestBase Wait for recoveries to finish - collection: forwardingCollection failOnTimeout:true timeout (sec):100
[junit4] 2> 229304 INFO (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[2437EAE19FD1F665]) [ ] o.a.s.c.AbstractDistribZkTestBase Recoveries finished - collection: forwardingCollection
[junit4] 2> 229310 INFO (qtp22995269-2020) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.S.Request [forwardingCollection_shard1_replica_n1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 229311 WARN (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[2437EAE19FD1F665]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=user&p=user&t=test&e=1515276371762&s=yvOI3QeXA09DotG7G4SqisRAwnU="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:06:11 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:06:11 GMT
[junit4] 2> 229314 INFO (qtp19444460-2023) [n:127.0.0.1:43967_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores
[junit4] 2> 229317 INFO (qtp22995269-2020) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.S.Request [forwardingCollection_shard1_replica_n1] webapp=/solr path=/select params={q=*:*&wt=javabin&version=2} hits=0 status=0 QTime=0
[junit4] 2> 229318 WARN (qtp19444460-2023) [n:127.0.0.1:43967_solr ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=$&p=$&t=test&e=1515276371769&s=Lz8R50TGovk5QL9Xf1JO6xwSyEI="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:06:11 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:06:11 GMT
[junit4] 2> 229318 WARN (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[2437EAE19FD1F665]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=user&p=user&t=test&e=1515276371766&s=HvT6xS0BXPmO8cXc8jn2EAON+6M="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:06:11 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:06:11 GMT
[junit4] 2> 229319 WARN (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[2437EAE19FD1F665]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=$&p=$&t=test&e=1515276371769&s=Lz8R50TGovk5QL9Xf1JO6xwSyEI="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:06:11 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:06:11 GMT
[junit4] 2> 229319 INFO (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testForwarding
[junit4] 2> 229332 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateGroup-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyValidateGroup
[junit4] 2> 229340 INFO (qtp22995269-2012) [n:127.0.0.1:37169_solr ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params doAs=jenkins&action=LIST&wt=javabin&version=2 and sendToOCPQueue=true
[junit4] 2> 229340 INFO (qtp22995269-2012) [n:127.0.0.1:37169_solr ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={doAs=jenkins&action=LIST&wt=javabin&version=2} status=0 QTime=0
[junit4] 2> 229341 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateGroup-seed#[2437EAE19FD1F665]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=anyHostUsersGroup&p=anyHostUsersGroup&t=test&e=1515276371786&s=D7tBfy5DoUHwyHinR7Tq+p9wz6w="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:06:11 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:06:11 GMT
[junit4] 2> 229341 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateGroup-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyValidateGroup
[junit4] 2> 229357 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyUnknownRemote-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyUnknownRemote
[junit4] 2> 240166 WARN (jetty-launcher-520-thread-1-SendThread(127.0.0.1:38183)) [n:127.0.0.1:37169_solr ] o.a.z.ClientCnxn Client session timed out, have not heard from server in 14280ms for sessionid 0x160cb5cfbd30008
[junit4] 2> 240166 WARN (jetty-launcher-520-thread-2-SendThread(127.0.0.1:38183)) [n:127.0.0.1:43967_solr ] o.a.z.ClientCnxn Client session timed out, have not heard from server in 14280ms for sessionid 0x160cb5cfbd30007
[junit4] 2> 240166 WARN (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[2437EAE19FD1F665]-SendThread(127.0.0.1:38183)) [ ] o.a.z.ClientCnxn Client session timed out, have not heard from server in 10862ms for sessionid 0x160cb5cfbd3000b
[junit4] 2> 240166 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x160cb5cfbd30008, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 240167 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x160cb5cfbd30007, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 240168 INFO (OverseerCollectionConfigSetProcessor-99302792024489989-127.0.0.1:37169_solr-n_0000000000) [n:127.0.0.1:37169_solr ] o.a.s.c.OverseerTaskQueue Response ZK path: /overseer/collection-queue-work/qnr-0000000000 doesn't exist. Requestor may have disconnected from ZooKeeper
[junit4] 2> 240172 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyUnknownRemote-seed#[2437EAE19FD1F665]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=localHostAnyGroup&p=localHostAnyGroup&t=test&e=1515276371809&s=wW1HM9KI8u+XUiDyeowsWkW1ktI="; Path=/; Domain=127.0.0.1; Expires= , 06- -2018 22:06:11 GMT; HttpOnly". Invalid 'expires' attribute: , 06- -2018 22:06:11 GMT
[junit4] 2> 240172 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyUnknownRemote-seed#[2437EAE19FD1F665]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyUnknownRemote
[junit4] 2> 240270 INFO (jetty-closer-521-thread-1) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@170669c{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 240270 INFO (jetty-closer-521-thread-2) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@d98b6{HTTP/1.1,[http/1.1]}{127.0.0.1:0}
[junit4] 2> 240270 INFO (jetty-closer-521-thread-1) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=4981192
[junit4] 2> 240271 INFO (jetty-closer-521-thread-2) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=16374435
[junit4] 2> 240271 INFO (jetty-closer-521-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 240271 INFO (jetty-closer-521-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null
[junit4] 2> 240271 INFO (jetty-closer-521-thread-1) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@666b76: rootName = solr_37169, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@1685d63
[junit4] 2> 240271 INFO (jetty-closer-521-thread-2) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@131ec10: rootName = solr_43967, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@ffb3fc
[junit4] 2> 240292 INFO (jetty-closer-521-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
[junit4] 2> 240292 INFO (jetty-closer-521-thread-2) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@be9062: rootName = solr_43967, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@123bc09
[junit4] 2> 240295 INFO (jetty-closer-521-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null
[junit4] 2> 240295 INFO (jetty-closer-521-thread-1) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@14497cd: rootName = solr_37169, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@123bc09
[junit4] 2> 240308 INFO (jetty-closer-521-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 240309 INFO (jetty-closer-521-thread-2) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@1bcb7c6: rootName = solr_43967, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@4bf397
[junit4] 2> 240313 INFO (jetty-closer-521-thread-2) [ ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:43967_solr
[junit4] 2> 240314 INFO (jetty-closer-521-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
[junit4] 2> 240314 INFO (zkCallback-536-thread-3-processing-n:127.0.0.1:37169_solr) [n:127.0.0.1:37169_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 240314 INFO (zkCallback-538-thread-1-processing-n:127.0.0.1:43967_solr) [n:127.0.0.1:43967_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1)
[junit4] 2> 240315 INFO (jetty-closer-521-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null
[junit4] 2> 240315 INFO (jetty-closer-521-thread-1) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@1af44d5: rootName = solr_37169, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@4bf397
[junit4] 2> 240316 INFO (jetty-closer-521-thread-1) [ ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:37169_solr
[junit4] 2> 240316 INFO (jetty-closer-521-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null
[junit4] 2> 240317 INFO (zkCallback-536-thread-3-processing-n:127.0.0.1:37169_solr) [n:127.0.0.1:37169_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (0)
[junit4] 2> 240317 INFO (coreCloseExecutor-719-thread-1) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.SolrCore [forwardingCollection_shard1_replica_n1] CLOSING SolrCore org.apache.solr.core.SolrCore@960c81
[junit4] 2> 240317 INFO (coreCloseExecutor-719-thread-1) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.forwardingCollection.shard1.replica_n1, tag=9833601
[junit4] 2> 240317 INFO (zkCallback-536-thread-2-processing-n:127.0.0.1:37169_solr) [n:127.0.0.1:37169_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forwardingCollection/state.json] for collection [forwardingCollection] has occurred - updating... (live nodes size: [0])
[junit4] 2> 240317 INFO (zkCallback-536-thread-1-processing-n:127.0.0.1:37169_solr) [n:127.0.0.1:37169_solr ] o.a.s.c.c.ZkStateReader A cluster state change: [WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/forwardingCollection/state.json] for collection [forwardingCollection] has occurred - updating... (live nodes size: [0])
[junit4] 2> 240318 INFO (coreCloseExecutor-719-thread-1) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@107f324: rootName = solr_37169, domain = solr.core.forwardingCollection.shard1.replica_n1, service url = null, agent id = null] for registry solr.core.forwardingCollection.shard1.replica_n1 / com.codahale.metrics.MetricRegistry@abc342
[junit4] 2> 240339 INFO (coreCloseExecutor-719-thread-1) [n:127.0.0.1:37169_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.forwardingCollection.shard1.leader, tag=9833601
[junit4] 2> 240341 INFO (jetty-closer-521-thread-1) [ ] o.a.s.c.Overseer Overseer (id=99302792024489989-127.0.0.1:37169_solr-n_0000000000) closing
[junit4] 2> 240341 INFO (OverseerStateUpdate-99302792024489989-127.0.0.1:37169_solr-n_0000000000) [n:127.0.0.1:37169_solr ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:37169_solr
[junit4] 2> 240341 WARN (OverseerAutoScalingTriggerThread-99302792024489989-127.0.0.1:37169_solr-n_0000000000) [n:127.0.0.1:37169_solr ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 240342 WARN (NIOServerCxn.Factory:0.0.0.0/0.0.0.0:0) [ ] o.a.z.s.NIOServerCnxn caught end of stream exception
[junit4] 2> EndOfStreamException: Unable to read additional data from client sessionid 0x160cb5cfbd30005, likely client has closed socket
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:239)
[junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:203)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 240342 ERROR (Thread[Thread-319,5,TGRP-TestSolrCloudWithSecureImpersonation]) [n:127.0.0.1:37169_solr ] o.a.h.s.t.d.AbstractDelegationTokenSecretManager ExpiredTokenRemover received java.lang.InterruptedException: sleep interrupted
[junit4] 2> 241179 INFO (jetty-closer-521-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@c410d7{/solr,null,UNAVAILABLE}
[junit4] 2> 241310 INFO (jetty-launcher-520-thread-2-EventThread) [n:127.0.0.1:43967_solr ] o.a.c.f.s.ConnectionStateManager State change: SUSPENDED
[junit4] 2> 241815 WARN (zkCallback-538-thread-1-processing-n:127.0.0.1:43967_solr) [n:127.0.0.1:43967_solr ] o.a.s.c.ZkController Unable to register nodeLost path for 127.0.0.1:43967_solr
[junit4] 2> org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /autoscaling/nodeLost/127.0.0.1:43967_solr
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4] 2> at org.apache.zookeeper.ZooKeeper.create(ZooKeeper.java:783)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.lambda$create$7(SolrZkClient.java:364)
[junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:60)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.create(SolrZkClient.java:364)
[junit4] 2> at org.apache.solr.cloud.ZkController.lambda$registerLiveNodesListener$2(ZkController.java:879)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.lambda$refreshLiveNodes$1(ZkStateReader.java:704)
[junit4] 2> at java.util.concurrent.ConcurrentHashMap$KeySetView.forEach(ConcurrentHashMap.java:4649)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.refreshLiveNodes(ZkStateReader.java:703)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.access$900(ZkStateReader.java:72)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader$LiveNodeWatcher.refreshAndWatch(ZkStateReader.java:1090)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader$LiveNodeWatcher.process(ZkStateReader.java:1085)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$1.lambda$process$1(SolrZkClient.java:268)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:266)
[junit4] 2> at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
[junit4] 2> at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 241816 ERROR (Thread[Thread-320,5,TGRP-TestSolrCloudWithSecureImpersonation]) [n:127.0.0.1:43967_solr ] o.a.h.s.t.d.AbstractDelegationTokenSecretManager ExpiredTokenRemover received java.lang.InterruptedException: sleep interrupted
[junit4] 2> 241819 INFO (jetty-closer-521-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@3a574{/solr,null,UNAVAILABLE}
[junit4] 2> 241819 ERROR (SUITE-TestSolrCloudWithSecureImpersonation-seed#[2437EAE19FD1F665]-worker) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes
[junit4] 2> 241820 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[2437EAE19FD1F665]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:38183 38183
[junit4] 2> 256840 INFO (Thread-302) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:38183 38183
[junit4] 2> 256841 WARN (Thread-302) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 3 /solr/aliases.json
[junit4] 2> 3 /solr/clusterprops.json
[junit4] 2> 2 /solr/security.json
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 6 /solr/collections/forwardingCollection/state.json
[junit4] 2> 4 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMKeyIdRoot
[junit4] 2> 3 /solr/clusterstate.json
[junit4] 2> 3 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMSeqNumRoot
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMMasterKeyRoot/DK_1
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMMasterKeyRoot/DK_3
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMMasterKeyRoot/DK_2
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMMasterKeyRoot/DK_4
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 3 /solr/live_nodes
[junit4] 2> 3 /solr/collections
[junit4] 2> 3 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMMasterKeyRoot
[junit4] 2> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMTokensRoot
[junit4] 2>
[junit4] 2> 256865 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[2437EAE19FD1F665]-worker) [ ] o.a.s.SolrTestCaseJ4 ------------------------------------------------------- Done waiting for tracked resources to be released
[junit4] 2> Jan 06, 2018 12:06:39 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 2 leaked thread(s).
[junit4] 2> 271328 ERROR (jetty-launcher-520-thread-2-EventThread) [n:127.0.0.1:43967_solr ] o.a.c.f.i.CuratorFrameworkImpl Watcher exception
[junit4] 2> java.lang.IllegalStateException: Client is not started
[junit4] 2> at com.google.common.base.Preconditions.checkState(Preconditions.java:149)
[junit4] 2> at org.apache.curator.CuratorZookeeperClient.getZooKeeper(CuratorZookeeperClient.java:113)
[junit4] 2> at org.apache.curator.framework.imps.CuratorFrameworkImpl.getZooKeeper(CuratorFrameworkImpl.java:477)
[junit4] 2> at org.apache.curator.framework.imps.NamespaceFacade.getZooKeeper(NamespaceFacade.java:112)
[junit4] 2> at org.apache.curator.framework.imps.GetDataBuilderImpl$4.call(GetDataBuilderImpl.java:302)
[junit4] 2> at org.apache.curator.framework.imps.GetDataBuilderImpl$4.call(GetDataBuilderImpl.java:291)
[junit4] 2> at org.apache.curator.RetryLoop.callWithRetry(RetryLoop.java:107)
[junit4] 2> at org.apache.curator.framework.imps.GetDataBuilderImpl.pathInForeground(GetDataBuilderImpl.java:288)
[junit4] 2> at org.apache.curator.framework.imps.GetDataBuilderImpl.forPath(GetDataBuilderImpl.java:279)
[junit4] 2> at org.apache.curator.framework.imps.GetDataBuilderImpl.forPath(GetDataBuilderImpl.java:41)
[junit4] 2> at org.apache.curator.framework.recipes.shared.SharedValue.readValue(SharedValue.java:244)
[junit4] 2> at org.apache.curator.framework.recipes.shared.SharedValue.access$100(SharedValue.java:44)
[junit4] 2> at org.apache.curator.framework.recipes.shared.SharedValue$1.process(SharedValue.java:61)
[junit4] 2> at org.apache.curator.framework.imps.NamespaceWatcher.process(NamespaceWatcher.java:67)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:530)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:505)
[junit4] 2> Jan 06, 2018 12:06:59 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> SEVERE: 1 thread leaked from SUITE scope at org.apache.solr.cloud.TestSolrCloudWithSecureImpersonation:
[junit4] 2> 1) Thread[id=2062, name=jetty-launcher-520-thread-1-EventThread, state=TIMED_WAITING, group=TGRP-TestSolrCloudWithSecureImpersonation]
[junit4] 2> at sun.misc.Unsafe.park(Native Method)
[junit4] 2> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
[junit4] 2> at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277)
[junit4] 2> at org.apache.curator.CuratorZookeeperClient.internalBlockUntilConnectedOrTimedOut(CuratorZookeeperClient.java:323)
[junit4] 2> at org.apache.curator.RetryLoop.callWithRetry(RetryLoop.java:105)
[junit4] 2> at org.apache.curator.framework.imps.GetDataBuilderImpl.pathInForeground(GetDataBuilderImpl.java:288)
[junit4] 2> at org.apache.curator.framework.imps.GetDataBuilderImpl.forPath(GetDataBuilderImpl.java:279)
[junit4] 2> at org.apache.curator.framework.imps.GetDataBuilderImpl.forPath(GetDataBuilderImpl.java:41)
[junit4] 2> at org.apache.curator.framework.recipes.shared.SharedValue.readValue(SharedValue.java:244)
[junit4] 2> at org.apache.curator.framework.recipes.shared.SharedValue.access$100(SharedValue.java:44)
[junit4] 2> at org.apache.curator.framework.recipes.shared.SharedValue$1.process(SharedValue.java:61)
[junit4] 2> at org.apache.curator.framework.imps.NamespaceWatcher.process(NamespaceWatcher.java:67)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:530)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:505)
[junit4] 2> Jan 06, 2018 12:06:59 PM com.carrotsearch.randomizedtesting.ThreadLeakControl tryToInterruptAll
[junit4] 2> INFO: Starting to interrupt leaked threads:
[junit4] 2> 1) Thread[id=2062, name=jetty-launcher-520-thread-1-EventThread, state=TIMED_WAITING, group=TGRP-TestSolrCloudWithSecureImpersonation]
[junit4] 2> 276942 ERROR (jetty-launcher-520-thread-1-EventThread) [n:127.0.0.1:37169_solr ] o.a.c.f.i.CuratorFrameworkImpl Watcher exception
[junit4] 2> java.lang.InterruptedException
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1039)
[junit4] 2> at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
[junit4] 2> at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277)
[junit4] 2> at org.apache.curator.CuratorZookeeperClient.internalBlockUntilConnectedOrTimedOut(CuratorZookeeperClient.java:323)
[junit4] 2> at org.apache.curator.RetryLoop.callWithRetry(RetryLoop.java:105)
[junit4] 2> at org.apache.curator.framework.imps.GetDataBuilderImpl.pathInForeground(GetDataBuilderImpl.java:288)
[junit4] 2> at org.apache.curator.framework.imps.GetDataBuilderImpl.forPath(GetDataBuilderImpl.java:279)
[junit4] 2> at org.apache.curator.framework.imps.GetDataBuilderImpl.forPath(GetDataBuilderImpl.java:41)
[junit4] 2> at org.apache.curator.framework.recipes.shared.SharedValue.readValue(SharedValue.java:244)
[junit4] 2> at org.apache.curator.framework.recipes.shared.SharedValue.access$100(SharedValue.java:44)
[junit4] 2> at org.apache.curator.framework.recipes.shared.SharedValue$1.process(SharedValue.java:61)
[junit4] 2> at org.apache.curator.framework.imps.NamespaceWatcher.process(NamespaceWatcher.java:67)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:530)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:505)
[junit4] 2> Jan 06, 2018 12:06:59 PM com.carrotsearch.randomizedtesting.ThreadLeakControl tryToInterruptAll
[junit4] 2> INFO: All leaked threads terminated.
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene70): {}, docValues:{}, maxPointsInLeafNode=1721, maxMBSortInHeap=5.468140410476471, sim=Asserting(org.apache.lucene.search.similarities.AssertingSimilarity@1e64c1b), locale=ar-KW, timezone=America/Ensenada
[junit4] 2> NOTE: Linux 4.10.0-40-generic i386/Oracle Corporation 1.8.0_144 (32-bit)/cpus=8,threads=1,free=87418776,total=192352256
[junit4] 2> NOTE: All tests run in this JVM: [AssignBackwardCompatibilityTest, TestSolrQueryResponse, TestTriggerIntegration, TestDynamicLoading, TestUniqueKeyFieldResource, TestCSVLoader, V2StandaloneTest, TestBlendedInfixSuggestions, TestPolicyCloud, DocumentBuilderTest, ComputePlanActionTest, BufferStoreTest, TestDocTermOrds, TestSolrCloudWithSecureImpersonation]
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestSolrCloudWithSecureImpersonation -Dtests.seed=2437EAE19FD1F665 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar-KW -Dtests.timezone=America/Ensenada -Dtests.asserts=true -Dtests.file.encoding=US-ASCII
[junit4] ERROR 0.00s J0 | TestSolrCloudWithSecureImpersonation (suite) <<<
[junit4] > Throwable #1: com.carrotsearch.randomizedtesting.ThreadLeakError: 1 thread leaked from SUITE scope at org.apache.solr.cloud.TestSolrCloudWithSecureImpersonation:
[junit4] > 1) Thread[id=2062, name=jetty-launcher-520-thread-1-EventThread, state=TIMED_WAITING, group=TGRP-TestSolrCloudWithSecureImpersonation]
[junit4] > at sun.misc.Unsafe.park(Native Method)
[junit4] > at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
[junit4] > at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedNanos(AbstractQueuedSynchronizer.java:1037)
[junit4] > at java.util.concurrent.locks.AbstractQueuedSynchronizer.tryAcquireSharedNanos(AbstractQueuedSynchronizer.java:1328)
[junit4] > at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:277)
[junit4] > at org.apache.curator.CuratorZookeeperClient.internalBlockUntilConnectedOrTimedOut(CuratorZookeeperClient.java:323)
[junit4] > at org.apache.curator.RetryLoop.callWithRetry(RetryLoop.java:105)
[junit4] > at org.apache.curator.framework.imps.GetDataBuilderImpl.pathInForeground(GetDataBuilderImpl.java:288)
[junit4] > at org.apache.curator.framework.imps.GetDataBuilderImpl.forPath(GetDataBuilderImpl.java:279)
[junit4] > at org.apache.curator.framework.imps.GetDataBuilderImpl.forPath(GetDataBuilderImpl.java:41)
[junit4] > at org.apache.curator.framework.recipes.shared.SharedValue.readValue(SharedValue.java:244)
[junit4] > at org.apache.curator.framework.recipes.shared.SharedValue.access$100(SharedValue.java:44)
[junit4] > at org.apache.curator.framework.recipes.shared.SharedValue$1.process(SharedValue.java:61)
[junit4] > at org.apache.curator.framework.imps.NamespaceWatcher.process(NamespaceWatcher.java:67)
[junit4] > at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:530)
[junit4] > at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:505)
[junit4] > at __randomizedtesting.SeedInfo.seed([2437EAE19FD1F665]:0)
[junit4] Completed [66/766 (1!)] on J0 in 62.75s, 12 tests, 1 error <<< FAILURES!
[...truncated 46213 lines...]
[JENKINS] Lucene-Solr-master-Linux (64bit/jdk1.8.0_144) - Build #
21226 - Still Unstable!
Posted by Policeman Jenkins Server <je...@thetaphi.de>.
Build: https://jenkins.thetaphi.de/job/Lucene-Solr-master-Linux/21226/
Java: 64bit/jdk1.8.0_144 -XX:+UseCompressedOops -XX:+UseSerialGC
2 tests failed.
FAILED: org.apache.solr.cloud.TestAuthenticationFramework.testBasics
Error Message:
Error from server at http://127.0.0.1:40129/solr/testcollection_shard1_replica_n3: Expected mime type application/octet-stream but got text/html. <html> <head> <meta http-equiv="Content-Type" content="text/html;charset=ISO-8859-1"/> <title>Error 404 </title> </head> <body> <h2>HTTP ERROR: 404</h2> <p>Problem accessing /solr/testcollection_shard1_replica_n3/update. Reason: <pre> Can not find: /solr/testcollection_shard1_replica_n3/update</pre></p> <hr /><a href="http://eclipse.org/jetty">Powered by Jetty:// 9.3.20.v20170531</a><hr/> </body> </html>
Stack Trace:
org.apache.solr.client.solrj.impl.CloudSolrClient$RouteException: Error from server at http://127.0.0.1:40129/solr/testcollection_shard1_replica_n3: Expected mime type application/octet-stream but got text/html. <html>
<head>
<meta http-equiv="Content-Type" content="text/html;charset=ISO-8859-1"/>
<title>Error 404 </title>
</head>
<body>
<h2>HTTP ERROR: 404</h2>
<p>Problem accessing /solr/testcollection_shard1_replica_n3/update. Reason:
<pre> Can not find: /solr/testcollection_shard1_replica_n3/update</pre></p>
<hr /><a href="http://eclipse.org/jetty">Powered by Jetty:// 9.3.20.v20170531</a><hr/>
</body>
</html>
at __randomizedtesting.SeedInfo.seed([9705E427D041289D:AADD4A0BE8AF76ED]:0)
at org.apache.solr.client.solrj.impl.CloudSolrClient.directUpdate(CloudSolrClient.java:550)
at org.apache.solr.client.solrj.impl.CloudSolrClient.sendRequest(CloudSolrClient.java:1013)
at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:884)
at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:946)
at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:946)
at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:946)
at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:946)
at org.apache.solr.client.solrj.impl.CloudSolrClient.requestWithRetryOnStaleState(CloudSolrClient.java:946)
at org.apache.solr.client.solrj.impl.CloudSolrClient.request(CloudSolrClient.java:817)
at org.apache.solr.client.solrj.SolrRequest.process(SolrRequest.java:194)
at org.apache.solr.client.solrj.request.UpdateRequest.commit(UpdateRequest.java:233)
at org.apache.solr.cloud.TestAuthenticationFramework.collectionCreateSearchDeleteTwice(TestAuthenticationFramework.java:126)
at org.apache.solr.cloud.TestAuthenticationFramework.testBasics(TestAuthenticationFramework.java:74)
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 com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:934)
at com.carrotsearch.randomizedtesting.RandomizedRunner$9.evaluate(RandomizedRunner.java:970)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:984)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.lang.Thread.run(Thread.java:748)
Caused by: org.apache.solr.client.solrj.impl.HttpSolrClient$RemoteSolrException: Error from server at http://127.0.0.1:40129/solr/testcollection_shard1_replica_n3: Expected mime type application/octet-stream but got text/html. <html>
<head>
<meta http-equiv="Content-Type" content="text/html;charset=ISO-8859-1"/>
<title>Error 404 </title>
</head>
<body>
<h2>HTTP ERROR: 404</h2>
<p>Problem accessing /solr/testcollection_shard1_replica_n3/update. Reason:
<pre> Can not find: /solr/testcollection_shard1_replica_n3/update</pre></p>
<hr /><a href="http://eclipse.org/jetty">Powered by Jetty:// 9.3.20.v20170531</a><hr/>
</body>
</html>
at org.apache.solr.client.solrj.impl.HttpSolrClient.executeMethod(HttpSolrClient.java:607)
at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:255)
at org.apache.solr.client.solrj.impl.HttpSolrClient.request(HttpSolrClient.java:244)
at org.apache.solr.client.solrj.impl.LBHttpSolrClient.doRequest(LBHttpSolrClient.java:483)
at org.apache.solr.client.solrj.impl.LBHttpSolrClient.request(LBHttpSolrClient.java:413)
at org.apache.solr.client.solrj.impl.CloudSolrClient.lambda$directUpdate$0(CloudSolrClient.java:527)
at java.util.concurrent.FutureTask.run(FutureTask.java:266)
at org.apache.solr.common.util.ExecutorUtil$MDCAwareThreadPoolExecutor.lambda$execute$0(ExecutorUtil.java:188)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
... 1 more
FAILED: org.apache.solr.cloud.autoscaling.sim.TestComputePlanAction.testNodeWithMultipleReplicasLost
Error Message:
Stack Trace:
java.util.ConcurrentModificationException
at __randomizedtesting.SeedInfo.seed([9705E427D041289D:A7C505A55833C9C1]:0)
at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:901)
at java.util.ArrayList$Itr.next(ArrayList.java:851)
at org.apache.solr.cloud.autoscaling.sim.SimSolrCloudTestCase.tearDown(SimSolrCloudTestCase.java:141)
at sun.reflect.GeneratedMethodAccessor26.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:498)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$10.evaluate(RandomizedRunner.java:992)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:49)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:817)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:468)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:943)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:829)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:879)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:890)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:57)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:45)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:41)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:40)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:53)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:47)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:64)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:54)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:368)
at java.lang.Thread.run(Thread.java:748)
Build Log:
[...truncated 12548 lines...]
[junit4] Suite: org.apache.solr.cloud.autoscaling.sim.TestComputePlanAction
[junit4] 2> 847704 INFO (SUITE-TestComputePlanAction-seed#[9705E427D041289D]-worker) [ ] o.a.s.SolrTestCaseJ4 SecureRandom sanity checks: test.solr.allowed.securerandom=null & java.security.egd=file:/dev/./urandom
[junit4] 2> Creating dataDir: /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.autoscaling.sim.TestComputePlanAction_9705E427D041289D-001/init-core-data-001
[junit4] 2> 847705 WARN (SUITE-TestComputePlanAction-seed#[9705E427D041289D]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=1 numCloses=1
[junit4] 2> 847705 INFO (SUITE-TestComputePlanAction-seed#[9705E427D041289D]-worker) [ ] o.a.s.SolrTestCaseJ4 Using PointFields (NUMERIC_POINTS_SYSPROP=true) w/NUMERIC_DOCVALUES_SYSPROP=false
[junit4] 2> 847707 INFO (SUITE-TestComputePlanAction-seed#[9705E427D041289D]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (false) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN)
[junit4] 2> 847719 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .autoAddReplicas trigger
[junit4] 2> 847719 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 0
[junit4] 2> 847719 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10000_solr]
[junit4] 2> 847719 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 0, lastZnodeVersion -1
[junit4] 2> 847719 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 0
[junit4] 2> 847719 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 847719 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 0, lastZnodeVersion 0
[junit4] 2> 847720 DEBUG (ScheduledTrigger-2957-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 847721 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testNodeWithMultipleReplicasLost
[junit4] 2> 847721 DEBUG (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 1
[junit4] 2> 847721 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 1
[junit4] 2> 847722 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 847722 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 847722 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 1, lastZnodeVersion 1
[junit4] 2> 847722 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 847722 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 847723 DEBUG (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 847723 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .autoAddReplicas trigger
[junit4] 2> 847723 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 2
[junit4] 2> 847723 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10000_solr]
[junit4] 2> 847723 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion -1
[junit4] 2> 847723 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 2
[junit4] 2> 847723 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 847723 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 2, lastZnodeVersion 2
[junit4] 2> 847723 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 847744 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 847764 DEBUG (ScheduledTrigger-2960-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 847784 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 847804 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 847825 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 847825 DEBUG (simCloudManagerPool-2959-thread-1) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 847826 DEBUG (simCloudManagerPool-2959-thread-1) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 3
[junit4] 2> 847826 DEBUG (simCloudManagerPool-2959-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10000_solr]
[junit4] 2> 847826 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 3
[junit4] 2> 847826 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 847826 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 3, lastZnodeVersion 3
[junit4] 2> 847826 DEBUG (simCloudManagerPool-2959-thread-2) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 847827 DEBUG (simCloudManagerPool-2959-thread-2) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 4
[junit4] 2> 847827 DEBUG (simCloudManagerPool-2959-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10000_solr]
[junit4] 2> 847827 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 4
[junit4] 2> 847827 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 847827 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 4, lastZnodeVersion 4
[junit4] 2> 847845 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 847865 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 847885 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 847905 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 847926 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 847944 DEBUG (simCloudManagerPool-2959-thread-3) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 847944 DEBUG (simCloudManagerPool-2959-thread-3) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 5
[junit4] 2> 847944 DEBUG (simCloudManagerPool-2959-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr, 127.0.0.1:10002_solr, 127.0.0.1:10003_solr]
[junit4] 2> 847944 DEBUG (simCloudManagerPool-2959-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10000_solr, 127.0.0.1:10002_solr, 127.0.0.1:10003_solr]
[junit4] 2> 847944 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 5
[junit4] 2> 847944 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 847945 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 5, lastZnodeVersion 5
[junit4] 2> 847945 DEBUG (ScheduledTrigger-2960-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 4
[junit4] 2> 847945 DEBUG (simCloudManagerPool-2959-thread-4) [ ] o.a.s.c.o.ClusterStateMutator building a new cName: testNodeWithMultipleReplicasLost
[junit4] 2> 847946 DEBUG (ScheduledTrigger-2960-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 4
[junit4] 2> 847959 DEBUG (simCloudManagerPool-2959-thread-4) [ ] o.a.s.c.s.c.a.PolicyHelper Creating a new session
[junit4] 2> 847962 DEBUG (simCloudManagerPool-2959-thread-4) [ ] o.a.s.c.s.c.a.PolicyHelper New session created
[junit4] 2> 847965 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 4
[junit4] 2> 847966 DEBUG (ScheduledTrigger-2960-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 4
[junit4] 2> 847967 INFO (simCloudManagerPool-2959-thread-4) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession, curr-time 2952171157 sessionWrapper.createTime 2952170905605461, this.sessionWrapper.createTime 2952170905605461
[junit4] 2> 847967 DEBUG (simCloudManagerPool-2959-thread-4) [ ] o.a.s.c.s.c.a.PolicyHelper session set to NULL
[junit4] 2> 847986 DEBUG (ScheduledTrigger-2960-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 4
[junit4] 2> 847986 DEBUG (ScheduledTrigger-2960-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 4
[junit4] 2> 848007 DEBUG (ScheduledTrigger-2960-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 4
[junit4] 2> 848007 DEBUG (ScheduledTrigger-2960-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 4
[junit4] 2> 848027 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 4
[junit4] 2> 848027 DEBUG (ScheduledTrigger-2960-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 4
[junit4] 2> 848033 DEBUG (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction -- cluster state: znodeVersion: 2
[junit4] 2> live nodes:[127.0.0.1:10001_solr, 127.0.0.1:10000_solr, 127.0.0.1:10002_solr, 127.0.0.1:10003_solr]
[junit4] 2> collections:{testNodeWithMultipleReplicasLost=DocCollection(testNodeWithMultipleReplicasLost//clusterstate.json/1)={
[junit4] 2> "replicationFactor":"3",
[junit4] 2> "pullReplicas":"0",
[junit4] 2> "router":{"name":"compositeId"},
[junit4] 2> "maxShardsPerNode":"1",
[junit4] 2> "autoAddReplicas":"false",
[junit4] 2> "nrtReplicas":"3",
[junit4] 2> "tlogReplicas":"0",
[junit4] 2> "autoCreated":"true",
[junit4] 2> "shards":{
[junit4] 2> "shard2":{
[junit4] 2> "replicas":{
[junit4] 2> "core_node6":{
[junit4] 2> "node_name":"127.0.0.1:10002_solr",
[junit4] 2> "core":"testNodeWithMultipleReplicasLost_shard2_replica_n6",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000},
[junit4] 2> "core_node4":{
[junit4] 2> "node_name":"127.0.0.1:10001_solr",
[junit4] 2> "core":"testNodeWithMultipleReplicasLost_shard2_replica_n4",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000},
[junit4] 2> "core_node5":{
[junit4] 2> "node_name":"127.0.0.1:10000_solr",
[junit4] 2> "core":"testNodeWithMultipleReplicasLost_shard2_replica_n5",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000}},
[junit4] 2> "range":"0-7fffffff",
[junit4] 2> "state":"active"},
[junit4] 2> "shard1":{
[junit4] 2> "replicas":{
[junit4] 2> "core_node1":{
[junit4] 2> "node_name":"127.0.0.1:10003_solr",
[junit4] 2> "core":"testNodeWithMultipleReplicasLost_shard1_replica_n1",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000},
[junit4] 2> "core_node2":{
[junit4] 2> "node_name":"127.0.0.1:10002_solr",
[junit4] 2> "core":"testNodeWithMultipleReplicasLost_shard1_replica_n2",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000},
[junit4] 2> "core_node3":{
[junit4] 2> "node_name":"127.0.0.1:10000_solr",
[junit4] 2> "core":"testNodeWithMultipleReplicasLost_shard1_replica_n3",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000}},
[junit4] 2> "range":"80000000-ffffffff",
[junit4] 2> "state":"active"}}}}
[junit4] 2> 848037 DEBUG (simCloudManagerPool-2959-thread-12) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testNodeWithMultipleReplicasLost / shard1: {"core_node1":{
[junit4] 2> "node_name":"127.0.0.1:10003_solr",
[junit4] 2> "core":"testNodeWithMultipleReplicasLost_shard1_replica_n1",
[junit4] 2> "leader":"true",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000,
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"testNodeWithMultipleReplicasLost"}}
[junit4] 2> 848037 DEBUG (simCloudManagerPool-2959-thread-11) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testNodeWithMultipleReplicasLost / shard2: {"core_node6":{
[junit4] 2> "node_name":"127.0.0.1:10002_solr",
[junit4] 2> "core":"testNodeWithMultipleReplicasLost_shard2_replica_n6",
[junit4] 2> "leader":"true",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000,
[junit4] 2> "shard":"shard2",
[junit4] 2> "collection":"testNodeWithMultipleReplicasLost"}}
[junit4] 2> 848047 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 3
[junit4] 2> 848047 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Tracking lost node: 127.0.0.1:10000_solr
[junit4] 2> 848047 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 3
[junit4] 2> 848047 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Tracking lost node: 127.0.0.1:10000_solr
[junit4] 2> 848067 DEBUG (ScheduledTrigger-2960-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 3
[junit4] 2> 848067 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 3
[junit4] 2> 848067 DEBUG (ScheduledTrigger-2960-thread-4) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger firing registered processor for lost nodes: [127.0.0.1:10000_solr]
[junit4] 2> 848067 DEBUG (ScheduledTrigger-2960-thread-4) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"a7cfcd927905fT246xpgsof8dkbs8gpt21e6igk",
[junit4] 2> "source":"node_lost_trigger",
[junit4] 2> "eventTime":2952175183958111,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2952175183958111],
[junit4] 2> "nodeNames":["127.0.0.1:10000_solr"]}}
[junit4] 2> 848070 DEBUG (AutoscalingActionExecutor-2961-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"a7cfcd927905fT246xpgsof8dkbs8gpt21e6igk",
[junit4] 2> "source":"node_lost_trigger",
[junit4] 2> "eventTime":2952175183958111,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2952175183958111],
[junit4] 2> "_enqueue_time_":2952176203217861,
[junit4] 2> "nodeNames":["127.0.0.1:10000_solr"]}}
[junit4] 2> 848070 DEBUG (AutoscalingActionExecutor-2961-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- processing event: {
[junit4] 2> "id":"a7cfcd927905fT246xpgsof8dkbs8gpt21e6igk",
[junit4] 2> "source":"node_lost_trigger",
[junit4] 2> "eventTime":2952175183958111,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2952175183958111],
[junit4] 2> "_enqueue_time_":2952176203217861,
[junit4] 2> "nodeNames":["127.0.0.1:10000_solr"]}} with context properties: {BEFORE_ACTION=[compute_plan]}
[junit4] 2> 848070 DEBUG (AutoscalingActionExecutor-2961-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper Creating a new session
[junit4] 2> 848073 DEBUG (AutoscalingActionExecutor-2961-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper New session created
[junit4] 2> 848074 INFO (AutoscalingActionExecutor-2961-thread-1) [ ] o.a.s.c.a.ComputePlanAction Computed Plan: action=MOVEREPLICA&collection=testNodeWithMultipleReplicasLost&targetNode=127.0.0.1:10003_solr&inPlaceMove=true&replica=core_node5
[junit4] 2> 848074 INFO (AutoscalingActionExecutor-2961-thread-1) [ ] o.a.s.c.a.ComputePlanAction Computed Plan: action=MOVEREPLICA&collection=testNodeWithMultipleReplicasLost&targetNode=127.0.0.1:10001_solr&inPlaceMove=true&replica=core_node3
[junit4] 2> 848074 INFO (AutoscalingActionExecutor-2961-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession, curr-time 2952176530 sessionWrapper.createTime 2952176457814061, this.sessionWrapper.createTime 2952176457814061
[junit4] 2> 848074 DEBUG (AutoscalingActionExecutor-2961-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper session set to NULL
[junit4] 2> 848076 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction action=MOVEREPLICA&collection=testNodeWithMultipleReplicasLost&targetNode=127.0.0.1:10003_solr&inPlaceMove=true&replica=core_node5
[junit4] 2> 848076 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction action=MOVEREPLICA&collection=testNodeWithMultipleReplicasLost&targetNode=127.0.0.1:10001_solr&inPlaceMove=true&replica=core_node3
[junit4] 2> 848077 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction -------------_ FINAL STATE --------------
[junit4] 2> 848077 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction * Node values: {
[junit4] 2> "127.0.0.1:10001_solr":{
[junit4] 2> "sysprop.java.vendor":"Oracle Corporation",
[junit4] 2> "cores":1,
[junit4] 2> "host":"127.0.0.1",
[junit4] 2> "freedisk":990,
[junit4] 2> "sysprop.java.version":"1.8.0_144",
[junit4] 2> "ip_1":"127",
[junit4] 2> "ip_3":"0",
[junit4] 2> "ip_2":"0",
[junit4] 2> "ip_4":"1",
[junit4] 2> "node":"127.0.0.1:10001_solr",
[junit4] 2> "metrics:solr.jvm:buffers.direct.Count":0,
[junit4] 2> "port":10001,
[junit4] 2> "heapUsage":123450000,
[junit4] 2> "sysLoadAvg":1.0,
[junit4] 2> "metrics:solr.node:ADMIN./admin/authorization.clientErrors:count":0},
[junit4] 2> "127.0.0.1:10000_solr":{
[junit4] 2> "sysprop.java.vendor":"Oracle Corporation",
[junit4] 2> "cores":2,
[junit4] 2> "host":"127.0.0.1",
[junit4] 2> "freedisk":980,
[junit4] 2> "sysprop.java.version":"1.8.0_144",
[junit4] 2> "ip_1":"127",
[junit4] 2> "ip_3":"0",
[junit4] 2> "ip_2":"0",
[junit4] 2> "ip_4":"1",
[junit4] 2> "node":"127.0.0.1:10000_solr",
[junit4] 2> "metrics:solr.jvm:buffers.direct.Count":0,
[junit4] 2> "port":10000,
[junit4] 2> "heapUsage":123450000,
[junit4] 2> "sysLoadAvg":1.0,
[junit4] 2> "metrics:solr.node:ADMIN./admin/authorization.clientErrors:count":0},
[junit4] 2> "127.0.0.1:10002_solr":{
[junit4] 2> "sysprop.java.vendor":"Oracle Corporation",
[junit4] 2> "cores":2,
[junit4] 2> "host":"127.0.0.1",
[junit4] 2> "freedisk":980,
[junit4] 2> "sysprop.java.version":"1.8.0_144",
[junit4] 2> "ip_1":"127",
[junit4] 2> "ip_3":"0",
[junit4] 2> "ip_2":"0",
[junit4] 2> "ip_4":"1",
[junit4] 2> "node":"127.0.0.1:10002_solr",
[junit4] 2> "metrics:solr.jvm:buffers.direct.Count":0,
[junit4] 2> "port":10002,
[junit4] 2> "heapUsage":123450000,
[junit4] 2> "sysLoadAvg":1.0,
[junit4] 2> "metrics:solr.node:ADMIN./admin/authorization.clientErrors:count":0},
[junit4] 2> "127.0.0.1:10003_solr":{
[junit4] 2> "sysprop.java.vendor":"Oracle Corporation",
[junit4] 2> "cores":1,
[junit4] 2> "host":"127.0.0.1",
[junit4] 2> "freedisk":990,
[junit4] 2> "sysprop.java.version":"1.8.0_144",
[junit4] 2> "ip_1":"127",
[junit4] 2> "ip_3":"0",
[junit4] 2> "ip_2":"0",
[junit4] 2> "ip_4":"1",
[junit4] 2> "node":"127.0.0.1:10003_solr",
[junit4] 2> "metrics:solr.jvm:buffers.direct.Count":0,
[junit4] 2> "port":10003,
[junit4] 2> "heapUsage":123450000,
[junit4] 2> "sysLoadAvg":1.0,
[junit4] 2> "metrics:solr.node:ADMIN./admin/authorization.clientErrors:count":0}}
[junit4] 2> 848077 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction * Live nodes: [127.0.0.1:10001_solr, 127.0.0.1:10002_solr, 127.0.0.1:10003_solr]
[junit4] 2> 848078 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction * Collection testNodeWithMultipleReplicasLost state: DocCollection(testNodeWithMultipleReplicasLost//clusterstate.json/3)={
[junit4] 2> "replicationFactor":"3",
[junit4] 2> "pullReplicas":"0",
[junit4] 2> "router":{"name":"compositeId"},
[junit4] 2> "maxShardsPerNode":"1",
[junit4] 2> "autoAddReplicas":"false",
[junit4] 2> "nrtReplicas":"3",
[junit4] 2> "tlogReplicas":"0",
[junit4] 2> "autoCreated":"true",
[junit4] 2> "shards":{
[junit4] 2> "shard2":{
[junit4] 2> "replicas":{
[junit4] 2> "core_node6":{
[junit4] 2> "core":"testNodeWithMultipleReplicasLost_shard2_replica_n6",
[junit4] 2> "leader":"true",
[junit4] 2> "INDEX.sizeInBytes":123450000,
[junit4] 2> "node_name":"127.0.0.1:10002_solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT"},
[junit4] 2> "core_node4":{
[junit4] 2> "node_name":"127.0.0.1:10001_solr",
[junit4] 2> "core":"testNodeWithMultipleReplicasLost_shard2_replica_n4",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000},
[junit4] 2> "core_node5":{
[junit4] 2> "node_name":"127.0.0.1:10000_solr",
[junit4] 2> "core":"testNodeWithMultipleReplicasLost_shard2_replica_n5",
[junit4] 2> "state":"down",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000}},
[junit4] 2> "range":"0-7fffffff",
[junit4] 2> "state":"active"},
[junit4] 2> "shard1":{
[junit4] 2> "replicas":{
[junit4] 2> "core_node1":{
[junit4] 2> "core":"testNodeWithMultipleReplicasLost_shard1_replica_n1",
[junit4] 2> "leader":"true",
[junit4] 2> "INDEX.sizeInBytes":123450000,
[junit4] 2> "node_name":"127.0.0.1:10003_solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT"},
[junit4] 2> "core_node2":{
[junit4] 2> "node_name":"127.0.0.1:10002_solr",
[junit4] 2> "core":"testNodeWithMultipleReplicasLost_shard1_replica_n2",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000},
[junit4] 2> "core_node3":{
[junit4] 2> "node_name":"127.0.0.1:10000_solr",
[junit4] 2> "core":"testNodeWithMultipleReplicasLost_shard1_replica_n3",
[junit4] 2> "state":"down",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000}},
[junit4] 2> "range":"80000000-ffffffff",
[junit4] 2> "state":"active"}}}
[junit4] 2> 848078 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testNodeWithMultipleReplicasLost
[junit4] 2> 848078 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase
[junit4] 2>
[junit4] 2> 848078 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase #############################################
[junit4] 2> 848078 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ############ FINAL CLUSTER STATS ############
[junit4] 2> 848078 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase #############################################
[junit4] 2>
[junit4] 2> 848078 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Live nodes: 3
[junit4] 2> 848079 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Empty nodes: 0
[junit4] 2> 848079 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Dead nodes: 1
[junit4] 2> 848079 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## 127.0.0.1:10000_solr
[junit4] 2> 848079 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Collections: [testNodeWithMultipleReplicasLost]
[junit4] 2> 848080 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Max replicas per node: 2
[junit4] 2> 848080 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Min replicas per node: 1
[junit4] 2> 848080 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Total replicas: 4
[junit4] 2> 848080 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## * testNodeWithMultipleReplicasLost 4
[junit4] 2> 848081 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - active 4
[junit4] 2> 848081 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ######### Final Solr op counts ##########
[junit4] 2> 848081 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - CREATE 1
[junit4] 2> 848081 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - autoscaling 3
[junit4] 2> 848081 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - update 3
[junit4] 2> 848081 INFO (TEST-TestComputePlanAction.testNodeWithMultipleReplicasLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ######### Autoscaling event counts ###########
[junit4] 2> 848082 DEBUG (AutoscalingActionExecutor-2961-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 571 ms for event id=a7cfcd927905fT246xpgsof8dkbs8gpt21e6igk
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestComputePlanAction -Dtests.method=testNodeWithMultipleReplicasLost -Dtests.seed=9705E427D041289D -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=sr-BA -Dtests.timezone=Etc/GMT+8 -Dtests.asserts=true -Dtests.file.encoding=US-ASCII
[junit4] ERROR 0.36s J0 | TestComputePlanAction.testNodeWithMultipleReplicasLost <<<
[junit4] > Throwable #1: java.util.ConcurrentModificationException
[junit4] > at __randomizedtesting.SeedInfo.seed([9705E427D041289D:A7C505A55833C9C1]:0)
[junit4] > at java.util.ArrayList$Itr.checkForComodification(ArrayList.java:901)
[junit4] > at java.util.ArrayList$Itr.next(ArrayList.java:851)
[junit4] > at org.apache.solr.cloud.autoscaling.sim.SimSolrCloudTestCase.tearDown(SimSolrCloudTestCase.java:141)
[junit4] > at java.lang.Thread.run(Thread.java:748)
[junit4] 2> 848088 DEBUG (ScheduledTrigger-2960-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 3
[junit4] 2> 848090 DEBUG (ScheduledTrigger-2960-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 3
[junit4] 2> 848091 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testNodeLost
[junit4] 2> 848092 DEBUG (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 6
[junit4] 2> 848092 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 6
[junit4] 2> 848092 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeLost markers
[junit4] 2> 848092 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 848092 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 6, lastZnodeVersion 6
[junit4] 2> 848092 INFO (simCloudManagerPool-2959-thread-17) [ ] o.a.s.c.ActionThrottle Throttling leader attempts - waiting for 2152ms
[junit4] 2> 848092 INFO (simCloudManagerPool-2959-thread-18) [ ] o.a.s.c.ActionThrottle Throttling leader attempts - waiting for 2146ms
[junit4] 2> 848092 INFO (simCloudManagerPool-2959-thread-19) [ ] o.a.s.c.ActionThrottle Throttling leader attempts - waiting for 2137ms
[junit4] 2> 848092 DEBUG (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimNodeStateProvider - removing dead node values: 127.0.0.1:10000_solr
[junit4] 2> 848092 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 848092 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 848093 DEBUG (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 848093 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .autoAddReplicas trigger
[junit4] 2> 848093 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 7
[junit4] 2> 848093 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr]
[junit4] 2> 848093 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 7, lastZnodeVersion -1
[junit4] 2> 848093 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 7
[junit4] 2> 848094 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 848094 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 7, lastZnodeVersion 7
[junit4] 2> 848094 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848114 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848135 DEBUG (ScheduledTrigger-2963-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848155 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848175 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848194 DEBUG (simCloudManagerPool-2962-thread-1) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 848194 DEBUG (simCloudManagerPool-2962-thread-1) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 8
[junit4] 2> 848194 DEBUG (simCloudManagerPool-2962-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr]
[junit4] 2> 848194 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 8
[junit4] 2> 848195 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 848195 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 8, lastZnodeVersion 8
[junit4] 2> 848195 DEBUG (simCloudManagerPool-2962-thread-2) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 848195 DEBUG (simCloudManagerPool-2962-thread-2) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 9
[junit4] 2> 848195 DEBUG (simCloudManagerPool-2962-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr]
[junit4] 2> 848195 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 9
[junit4] 2> 848195 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 848195 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 9, lastZnodeVersion 9
[junit4] 2> 848195 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848215 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848236 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848256 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848276 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848296 DEBUG (simCloudManagerPool-2962-thread-3) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 848296 DEBUG (simCloudManagerPool-2962-thread-3) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 10
[junit4] 2> 848296 DEBUG (simCloudManagerPool-2962-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10004_solr]
[junit4] 2> 848296 DEBUG (simCloudManagerPool-2962-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr, 127.0.0.1:10004_solr]
[junit4] 2> 848296 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 10
[junit4] 2> 848296 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 848296 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 848296 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 10, lastZnodeVersion 10
[junit4] 2> 848296 DEBUG (ScheduledTrigger-2963-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 2
[junit4] 2> 848296 DEBUG (simCloudManagerPool-2962-thread-4) [ ] o.a.s.c.o.ClusterStateMutator building a new cName: testNodeLost
[junit4] 2> 848307 DEBUG (simCloudManagerPool-2962-thread-4) [ ] o.a.s.c.s.c.a.PolicyHelper Creating a new session
[junit4] 2> 848308 DEBUG (simCloudManagerPool-2962-thread-4) [ ] o.a.s.c.s.c.a.PolicyHelper New session created
[junit4] 2> 848309 INFO (simCloudManagerPool-2962-thread-4) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession, curr-time 2952188278 sessionWrapper.createTime 2952188232047161, this.sessionWrapper.createTime 2952188232047161
[junit4] 2> 848309 DEBUG (simCloudManagerPool-2962-thread-4) [ ] o.a.s.c.s.c.a.PolicyHelper session set to NULL
[junit4] 2> 848316 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 848317 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 2
[junit4] 2> 848333 DEBUG (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction -- cluster state: znodeVersion: 8
[junit4] 2> live nodes:[127.0.0.1:10001_solr, 127.0.0.1:10004_solr]
[junit4] 2> collections:{testNodeLost=DocCollection(testNodeLost//clusterstate.json/7)={
[junit4] 2> "replicationFactor":"2",
[junit4] 2> "pullReplicas":"0",
[junit4] 2> "router":{"name":"compositeId"},
[junit4] 2> "maxShardsPerNode":"1",
[junit4] 2> "autoAddReplicas":"false",
[junit4] 2> "nrtReplicas":"2",
[junit4] 2> "tlogReplicas":"0",
[junit4] 2> "autoCreated":"true",
[junit4] 2> "shards":{"shard1":{
[junit4] 2> "replicas":{
[junit4] 2> "core_node1":{
[junit4] 2> "node_name":"127.0.0.1:10004_solr",
[junit4] 2> "core":"testNodeLost_shard1_replica_n1",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000},
[junit4] 2> "core_node2":{
[junit4] 2> "node_name":"127.0.0.1:10001_solr",
[junit4] 2> "core":"testNodeLost_shard1_replica_n2",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000}},
[junit4] 2> "range":"80000000-7fffffff",
[junit4] 2> "state":"active"}}}}
[junit4] 2> 848336 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction Stopped_node : 127.0.0.1:10004_solr
[junit4] 2> 848337 DEBUG (ScheduledTrigger-2963-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 848337 DEBUG (simCloudManagerPool-2962-thread-7) [ ] o.a.s.c.a.s.SimClusterStateProvider -- elected new leader for testNodeLost / shard1: {"core_node2":{
[junit4] 2> "node_name":"127.0.0.1:10001_solr",
[junit4] 2> "core":"testNodeLost_shard1_replica_n2",
[junit4] 2> "leader":"true",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000,
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"testNodeLost"}}
[junit4] 2> 848337 DEBUG (ScheduledTrigger-2963-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Tracking lost node: 127.0.0.1:10004_solr
[junit4] 2> 848337 DEBUG (ScheduledTrigger-2963-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 2
[junit4] 2> 848337 DEBUG (ScheduledTrigger-2963-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Tracking lost node: 127.0.0.1:10004_solr
[junit4] 2> 848357 DEBUG (ScheduledTrigger-2963-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 2
[junit4] 2> 848357 DEBUG (ScheduledTrigger-2963-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 848377 DEBUG (ScheduledTrigger-2963-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 2
[junit4] 2> 848377 DEBUG (ScheduledTrigger-2963-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 848398 DEBUG (ScheduledTrigger-2963-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 2
[junit4] 2> 848398 DEBUG (ScheduledTrigger-2963-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 848418 DEBUG (ScheduledTrigger-2963-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 2
[junit4] 2> 848418 DEBUG (ScheduledTrigger-2963-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 848438 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 848438 DEBUG (ScheduledTrigger-2963-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 2
[junit4] 2> 848458 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 848458 DEBUG (ScheduledTrigger-2963-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 2
[junit4] 2> 848478 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 848478 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: node_lost_trigger with currently live nodes: 2
[junit4] 2> 848478 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.NodeLostTrigger NodeLostTrigger firing registered processor for lost nodes: [127.0.0.1:10004_solr]
[junit4] 2> 848479 DEBUG (ScheduledTrigger-2963-thread-1) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"a7d00390084c5T246xpgsof8dkbs8gpt21e6igp",
[junit4] 2> "source":"node_lost_trigger",
[junit4] 2> "eventTime":2952189676913861,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2952189676913861],
[junit4] 2> "nodeNames":["127.0.0.1:10004_solr"]}}
[junit4] 2> 848481 DEBUG (AutoscalingActionExecutor-2964-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"a7d00390084c5T246xpgsof8dkbs8gpt21e6igp",
[junit4] 2> "source":"node_lost_trigger",
[junit4] 2> "eventTime":2952189676913861,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2952189676913861],
[junit4] 2> "_enqueue_time_":2952196756341861,
[junit4] 2> "nodeNames":["127.0.0.1:10004_solr"]}}
[junit4] 2> 848481 DEBUG (AutoscalingActionExecutor-2964-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- processing event: {
[junit4] 2> "id":"a7d00390084c5T246xpgsof8dkbs8gpt21e6igp",
[junit4] 2> "source":"node_lost_trigger",
[junit4] 2> "eventTime":2952189676913861,
[junit4] 2> "eventType":"NODELOST",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2952189676913861],
[junit4] 2> "_enqueue_time_":2952196756341861,
[junit4] 2> "nodeNames":["127.0.0.1:10004_solr"]}} with context properties: {BEFORE_ACTION=[compute_plan]}
[junit4] 2> 848481 DEBUG (AutoscalingActionExecutor-2964-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper Creating a new session
[junit4] 2> 848486 DEBUG (AutoscalingActionExecutor-2964-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper New session created
[junit4] 2> 848487 INFO (AutoscalingActionExecutor-2964-thread-1) [ ] o.a.s.c.a.ComputePlanAction Computed Plan: action=MOVEREPLICA&collection=testNodeLost&targetNode=127.0.0.1:10005_solr&inPlaceMove=true&replica=core_node1
[junit4] 2> 848487 INFO (AutoscalingActionExecutor-2964-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession, curr-time 2952197157 sessionWrapper.createTime 2952197138904111, this.sessionWrapper.createTime 2952197138904111
[junit4] 2> 848487 DEBUG (AutoscalingActionExecutor-2964-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper session set to NULL
[junit4] 2> 848487 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction -------------_ FINAL STATE --------------
[junit4] 2> 848487 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction * Node values: {
[junit4] 2> "127.0.0.1:10001_solr":{
[junit4] 2> "sysprop.java.vendor":"Oracle Corporation",
[junit4] 2> "cores":1,
[junit4] 2> "host":"127.0.0.1",
[junit4] 2> "freedisk":980,
[junit4] 2> "sysprop.java.version":"1.8.0_144",
[junit4] 2> "ip_1":"127",
[junit4] 2> "ip_3":"0",
[junit4] 2> "ip_2":"0",
[junit4] 2> "ip_4":"1",
[junit4] 2> "node":"127.0.0.1:10001_solr",
[junit4] 2> "metrics:solr.jvm:buffers.direct.Count":0,
[junit4] 2> "port":10001,
[junit4] 2> "heapUsage":123450000,
[junit4] 2> "sysLoadAvg":1.0,
[junit4] 2> "metrics:solr.node:ADMIN./admin/authorization.clientErrors:count":0},
[junit4] 2> "127.0.0.1:10004_solr":{
[junit4] 2> "sysprop.java.vendor":"Oracle Corporation",
[junit4] 2> "cores":1,
[junit4] 2> "host":"127.0.0.1",
[junit4] 2> "freedisk":990,
[junit4] 2> "sysprop.java.version":"1.8.0_144",
[junit4] 2> "ip_1":"127",
[junit4] 2> "ip_3":"0",
[junit4] 2> "ip_2":"0",
[junit4] 2> "ip_4":"1",
[junit4] 2> "node":"127.0.0.1:10004_solr",
[junit4] 2> "metrics:solr.jvm:buffers.direct.Count":0,
[junit4] 2> "port":10004,
[junit4] 2> "heapUsage":123450000,
[junit4] 2> "sysLoadAvg":1.0,
[junit4] 2> "metrics:solr.node:ADMIN./admin/authorization.clientErrors:count":0},
[junit4] 2> "127.0.0.1:10005_solr":{
[junit4] 2> "sysprop.java.vendor":"Oracle Corporation",
[junit4] 2> "cores":0,
[junit4] 2> "host":"127.0.0.1",
[junit4] 2> "freedisk":1000,
[junit4] 2> "sysprop.java.version":"1.8.0_144",
[junit4] 2> "ip_1":"127",
[junit4] 2> "ip_3":"0",
[junit4] 2> "ip_2":"0",
[junit4] 2> "ip_4":"1",
[junit4] 2> "node":"127.0.0.1:10005_solr",
[junit4] 2> "metrics:solr.jvm:buffers.direct.Count":0,
[junit4] 2> "port":10005,
[junit4] 2> "heapUsage":123450000,
[junit4] 2> "sysLoadAvg":1.0,
[junit4] 2> "metrics:solr.node:ADMIN./admin/authorization.clientErrors:count":0}}
[junit4] 2> 848487 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction * Live nodes: [127.0.0.1:10001_solr]
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction * Collection testNodeLost state: DocCollection(testNodeLost//clusterstate.json/9)={
[junit4] 2> "replicationFactor":"2",
[junit4] 2> "pullReplicas":"0",
[junit4] 2> "router":{"name":"compositeId"},
[junit4] 2> "maxShardsPerNode":"1",
[junit4] 2> "autoAddReplicas":"false",
[junit4] 2> "nrtReplicas":"2",
[junit4] 2> "tlogReplicas":"0",
[junit4] 2> "autoCreated":"true",
[junit4] 2> "shards":{"shard1":{
[junit4] 2> "replicas":{
[junit4] 2> "core_node1":{
[junit4] 2> "node_name":"127.0.0.1:10004_solr",
[junit4] 2> "core":"testNodeLost_shard1_replica_n1",
[junit4] 2> "state":"down",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000},
[junit4] 2> "core_node2":{
[junit4] 2> "core":"testNodeLost_shard1_replica_n2",
[junit4] 2> "leader":"true",
[junit4] 2> "INDEX.sizeInBytes":123450000,
[junit4] 2> "node_name":"127.0.0.1:10001_solr",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT"}},
[junit4] 2> "range":"80000000-7fffffff",
[junit4] 2> "state":"active"}}}
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testNodeLost
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase
[junit4] 2>
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase #############################################
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ############ FINAL CLUSTER STATS ############
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase #############################################
[junit4] 2>
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Live nodes: 1
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Empty nodes: 0
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Dead nodes: 2
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## 127.0.0.1:10004_solr
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## 127.0.0.1:10005_solr
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Collections: [testNodeLost]
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Max replicas per node: 1
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Min replicas per node: 1
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## Total replicas: 1
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## * testNodeLost 1
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - active 1
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ######### Final Solr op counts ##########
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - CREATE 1
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - autoscaling 3
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - update 2
[junit4] 2> 848488 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ######### Autoscaling event counts ###########
[junit4] 2> 848489 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## * Trigger: node_lost_trigger
[junit4] 2> 848489 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - BEFORE_ACTION 1
[junit4] 2> 848489 INFO (TEST-TestComputePlanAction.testNodeLost-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimSolrCloudTestCase ## - STARTED 1
[junit4] 2> 848508 DEBUG (AutoscalingActionExecutor-2964-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing took 1337 ms for event id=a7d00390084c5T246xpgsof8dkbs8gpt21e6igp
[junit4] 2> 848509 INFO (TEST-TestComputePlanAction.testNodeAdded-seed#[9705E427D041289D]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testNodeAdded
[junit4] 2> 848509 DEBUG (TEST-TestComputePlanAction.testNodeAdded-seed#[9705E427D041289D]) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 11
[junit4] 2> 848509 DEBUG (TEST-TestComputePlanAction.testNodeAdded-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimNodeStateProvider - removing dead node values: 127.0.0.1:10004_solr
[junit4] 2> 848509 DEBUG (TEST-TestComputePlanAction.testNodeAdded-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimNodeStateProvider - removing dead node values: 127.0.0.1:10005_solr
[junit4] 2> 848509 INFO (TEST-TestComputePlanAction.testNodeAdded-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.SimCloudManager === Restarting OverseerTriggerThread and clearing object cache...
[junit4] 2> 848509 WARN (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 848509 DEBUG (TEST-TestComputePlanAction.testNodeAdded-seed#[9705E427D041289D]) [ ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread has been closed explicitly
[junit4] 2> 848514 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Adding .autoAddReplicas trigger
[junit4] 2> 848514 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 12
[junit4] 2> 848514 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr]
[junit4] 2> 848514 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 12, lastZnodeVersion -1
[junit4] 2> 848514 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 12
[junit4] 2> 848514 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 848514 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 12, lastZnodeVersion 12
[junit4] 2> 848514 DEBUG (ScheduledTrigger-2966-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848534 DEBUG (ScheduledTrigger-2966-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848555 DEBUG (ScheduledTrigger-2966-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848575 DEBUG (ScheduledTrigger-2966-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848595 DEBUG (ScheduledTrigger-2966-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848615 DEBUG (simCloudManagerPool-2965-thread-1) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 848615 DEBUG (simCloudManagerPool-2965-thread-1) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 13
[junit4] 2> 848615 DEBUG (simCloudManagerPool-2965-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr]
[junit4] 2> 848615 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 13
[junit4] 2> 848615 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 848615 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 13, lastZnodeVersion 13
[junit4] 2> 848616 DEBUG (ScheduledTrigger-2966-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848616 DEBUG (simCloudManagerPool-2965-thread-2) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 848616 DEBUG (simCloudManagerPool-2965-thread-2) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 14
[junit4] 2> 848616 DEBUG (simCloudManagerPool-2965-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr]
[junit4] 2> 848616 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 14
[junit4] 2> 848616 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread -- clean old nodeAdded markers
[junit4] 2> 848616 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 14, lastZnodeVersion 14
[junit4] 2> 848636 DEBUG (ScheduledTrigger-2966-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848656 DEBUG (ScheduledTrigger-2966-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848676 DEBUG (ScheduledTrigger-2966-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848696 DEBUG (ScheduledTrigger-2966-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848717 DEBUG (ScheduledTrigger-2966-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848718 DEBUG (simCloudManagerPool-2965-thread-3) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 848719 DEBUG (simCloudManagerPool-2965-thread-3) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 15
[junit4] 2> 848719 DEBUG (simCloudManagerPool-2965-thread-3) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr]
[junit4] 2> 848719 DEBUG (simCloudManagerPool-2965-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10001_solr]
[junit4] 2> 848719 DEBUG (simCloudManagerPool-2965-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger instantiated with properties: {event=nodeAdded, waitFor=1, actions=[{name=compute_plan, class=solr.ComputePlanAction}, {name=test, class=org.apache.solr.cloud.autoscaling.sim.TestComputePlanAction$AssertingTriggerAction}], enabled=true}
[junit4] 2> 848720 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 15
[junit4] 2> 848720 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 15, lastZnodeVersion 15
[junit4] 2> 848720 DEBUG (ScheduledTrigger-2966-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 848720 DEBUG (ScheduledTrigger-2966-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 1
[junit4] 2> 848724 DEBUG (simCloudManagerPool-2965-thread-4) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 848724 DEBUG (simCloudManagerPool-2965-thread-4) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 16
[junit4] 2> 848725 DEBUG (simCloudManagerPool-2965-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr]
[junit4] 2> 848725 DEBUG (simCloudManagerPool-2965-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10001_solr]
[junit4] 2> 848725 DEBUG (simCloudManagerPool-2965-thread-4) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger instantiated with properties: {event=nodeAdded, waitFor=1, actions=[{name=compute_plan, class=solr.ComputePlanAction}, {name=test, class=org.apache.solr.cloud.autoscaling.sim.TestComputePlanAction$AssertingTriggerAction}], enabled=true}
[junit4] 2> 848725 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 16
[junit4] 2> 848725 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 16, lastZnodeVersion 16
[junit4] 2> 848725 DEBUG (simCloudManagerPool-2965-thread-5) [ ] o.a.s.c.o.ClusterStateMutator building a new cName: testNodeAdded
[junit4] 2> 848736 WARN (simCloudManagerPool-2965-thread-5) [ ] o.a.s.c.CreateCollectionCmd Specified number of replicas of 2 on collection testNodeAdded is higher than the number of Solr instances currently live or live and part of your createNodeSet(1). It's unusual to run two replica of the same slice on the same Solr-instance.
[junit4] 2> 848737 DEBUG (simCloudManagerPool-2965-thread-5) [ ] o.a.s.c.s.c.a.PolicyHelper Creating a new session
[junit4] 2> 848737 DEBUG (simCloudManagerPool-2965-thread-5) [ ] o.a.s.c.s.c.a.PolicyHelper New session created
[junit4] 2> 848737 INFO (simCloudManagerPool-2965-thread-5) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession, curr-time 2952209685 sessionWrapper.createTime 2952209671203361, this.sessionWrapper.createTime 2952209671203361
[junit4] 2> 848737 DEBUG (simCloudManagerPool-2965-thread-5) [ ] o.a.s.c.s.c.a.PolicyHelper session set to NULL
[junit4] 2> 848737 DEBUG (ScheduledTrigger-2966-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848741 DEBUG (ScheduledTrigger-2966-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 848741 DEBUG (ScheduledTrigger-2966-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 1
[junit4] 2> 848758 DEBUG (ScheduledTrigger-2966-thread-2) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 1
[junit4] 2> 848761 DEBUG (simCloudManagerPool-2965-thread-8) [ ] o.a.s.c.a.AutoScalingHandler Verified autoscaling configuration
[junit4] 2> 848761 DEBUG (simCloudManagerPool-2965-thread-8) [ ] o.a.s.c.a.OverseerTriggerThread Refreshing /autoscaling.json with znode version 17
[junit4] 2> 848761 DEBUG (simCloudManagerPool-2965-thread-8) [ ] o.a.s.c.a.NodeLostTrigger Initial livenodes: [127.0.0.1:10001_solr]
[junit4] 2> 848761 DEBUG (ScheduledTrigger-2966-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 848761 DEBUG (simCloudManagerPool-2965-thread-8) [ ] o.a.s.c.a.NodeAddedTrigger Initial livenodes: [127.0.0.1:10001_solr]
[junit4] 2> 848761 DEBUG (ScheduledTrigger-2966-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 1
[junit4] 2> 848761 DEBUG (simCloudManagerPool-2965-thread-8) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger instantiated with properties: {event=nodeAdded, waitFor=1, actions=[{name=compute_plan, class=solr.ComputePlanAction}, {name=test, class=org.apache.solr.cloud.autoscaling.sim.TestComputePlanAction$AssertingTriggerAction}], enabled=true}
[junit4] 2> 848761 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Processed trigger updates upto znodeVersion 17
[junit4] 2> 848761 DEBUG (Simulated OverseerAutoScalingTriggerThread) [ ] o.a.s.c.a.OverseerTriggerThread Current znodeVersion 17, lastZnodeVersion 17
[junit4] 2> 848778 DEBUG (ScheduledTrigger-2966-thread-1) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 848781 DEBUG (ScheduledTrigger-2966-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 848781 DEBUG (ScheduledTrigger-2966-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 2
[junit4] 2> 848781 DEBUG (ScheduledTrigger-2966-thread-3) [ ] o.a.s.c.a.NodeAddedTrigger Tracking new node: 127.0.0.1:10006_solr at time 2952211894223561
[junit4] 2> 848798 DEBUG (ScheduledTrigger-2966-thread-4) [ ] o.a.s.c.a.NodeLostTrigger Running NodeLostTrigger: .auto_add_replicas with currently live nodes: 2
[junit4] 2> 848802 DEBUG (ScheduledTrigger-2966-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Running NodeAddedTrigger node_added_trigger
[junit4] 2> 848802 DEBUG (ScheduledTrigger-2966-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger Found livenodes: 2
[junit4] 2> 848802 DEBUG (ScheduledTrigger-2966-thread-2) [ ] o.a.s.c.a.NodeAddedTrigger NodeAddedTrigger node_added_trigger firing registered processor for nodes: [127.0.0.1:10006_solr] added at times [2952211894223561], now=2952212911316211
[junit4] 2> 848802 DEBUG (ScheduledTrigger-2966-thread-2) [ ] o.a.s.c.a.ScheduledTriggers ++++++++ Cooldown inactive - processing event: {
[junit4] 2> "id":"a7d056541c2c9T246xpgsof8dkbs8gpt21e6igu",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":2952211894223561,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2952211894223561],
[junit4] 2> "nodeNames":["127.0.0.1:10006_solr"]}}
[junit4] 2> 848802 DEBUG (AutoscalingActionExecutor-2967-thread-1) [ ] o.a.s.c.a.ScheduledTriggers -- processing actions for {
[junit4] 2> "id":"a7d056541c2c9T246xpgsof8dkbs8gpt21e6igu",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":2952211894223561,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2952211894223561],
[junit4] 2> "_enqueue_time_":2952212918273861,
[junit4] 2> "nodeNames":["127.0.0.1:10006_solr"]}}
[junit4] 2> 848803 DEBUG (AutoscalingActionExecutor-2967-thread-1) [ ] o.a.s.c.a.ComputePlanAction -- processing event: {
[junit4] 2> "id":"a7d056541c2c9T246xpgsof8dkbs8gpt21e6igu",
[junit4] 2> "source":"node_added_trigger",
[junit4] 2> "eventTime":2952211894223561,
[junit4] 2> "eventType":"NODEADDED",
[junit4] 2> "properties":{
[junit4] 2> "eventTimes":[2952211894223561],
[junit4] 2> "_enqueue_time_":2952212918273861,
[junit4] 2> "nodeNames":["127.0.0.1:10006_solr"]}} with context properties: {BEFORE_ACTION=[compute_plan]}
[junit4] 2> 848803 DEBUG (AutoscalingActionExecutor-2967-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper Creating a new session
[junit4] 2> 848803 DEBUG (AutoscalingActionExecutor-2967-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper New session created
[junit4] 2> 848803 INFO (AutoscalingActionExecutor-2967-thread-1) [ ] o.a.s.c.a.ComputePlanAction Computed Plan: action=MOVEREPLICA&collection=testNodeAdded&targetNode=127.0.0.1:10006_solr&inPlaceMove=true&replica=core_node1
[junit4] 2> 848803 INFO (AutoscalingActionExecutor-2967-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper returnSession, curr-time 2952212997 sessionWrapper.createTime 2952212982508761, this.sessionWrapper.createTime 2952212982508761
[junit4] 2> 848803 DEBUG (AutoscalingActionExecutor-2967-thread-1) [ ] o.a.s.c.s.c.a.PolicyHelper session set to NULL
[junit4] 2> 848804 INFO (TEST-TestComputePlanAction.testNodeAdded-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction Node values: {
[junit4] 2> "127.0.0.1:10001_solr":{
[junit4] 2> "sysprop.java.vendor":"Oracle Corporation",
[junit4] 2> "cores":2,
[junit4] 2> "host":"127.0.0.1",
[junit4] 2> "freedisk":960,
[junit4] 2> "sysprop.java.version":"1.8.0_144",
[junit4] 2> "ip_1":"127",
[junit4] 2> "ip_3":"0",
[junit4] 2> "ip_2":"0",
[junit4] 2> "ip_4":"1",
[junit4] 2> "node":"127.0.0.1:10001_solr",
[junit4] 2> "metrics:solr.jvm:buffers.direct.Count":0,
[junit4] 2> "port":10001,
[junit4] 2> "heapUsage":123450000,
[junit4] 2> "sysLoadAvg":1.0,
[junit4] 2> "metrics:solr.node:ADMIN./admin/authorization.clientErrors:count":0},
[junit4] 2> "127.0.0.1:10006_solr":{
[junit4] 2> "sysprop.java.vendor":"Oracle Corporation",
[junit4] 2> "cores":0,
[junit4] 2> "host":"127.0.0.1",
[junit4] 2> "freedisk":1000,
[junit4] 2> "sysprop.java.version":"1.8.0_144",
[junit4] 2> "ip_1":"127",
[junit4] 2> "ip_3":"0",
[junit4] 2> "ip_2":"0",
[junit4] 2> "ip_4":"1",
[junit4] 2> "node":"127.0.0.1:10006_solr",
[junit4] 2> "metrics:solr.jvm:buffers.direct.Count":0,
[junit4] 2> "port":10006,
[junit4] 2> "heapUsage":123450000,
[junit4] 2> "sysLoadAvg":1.0,
[junit4] 2> "metrics:solr.node:ADMIN./admin/authorization.clientErrors:count":0}}
[junit4] 2> 848804 INFO (TEST-TestComputePlanAction.testNodeAdded-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction Live nodes: [127.0.0.1:10001_solr, 127.0.0.1:10006_solr], collection state: DocCollection(testNodeAdded//clusterstate.json/11)={
[junit4] 2> "replicationFactor":"2",
[junit4] 2> "pullReplicas":"0",
[junit4] 2> "router":{"name":"compositeId"},
[junit4] 2> "maxShardsPerNode":"1",
[junit4] 2> "autoAddReplicas":"false",
[junit4] 2> "nrtReplicas":"2",
[junit4] 2> "tlogReplicas":"0",
[junit4] 2> "autoCreated":"true",
[junit4] 2> "shards":{"shard1":{
[junit4] 2> "replicas":{
[junit4] 2> "core_node1":{
[junit4] 2> "node_name":"127.0.0.1:10001_solr",
[junit4] 2> "core":"testNodeAdded_shard1_replica_n1",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000},
[junit4] 2> "core_node2":{
[junit4] 2> "node_name":"127.0.0.1:10001_solr",
[junit4] 2> "core":"testNodeAdded_shard1_replica_n2",
[junit4] 2> "state":"active",
[junit4] 2> "type":"NRT",
[junit4] 2> "INDEX.sizeInBytes":123450000}},
[junit4] 2> "range":"80000000-7fffffff",
[junit4] 2> "state":"active"}}}
[junit4] 2> 848804 INFO (TEST-TestComputePlanAction.testNodeAdded-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction -------------_ FINAL STATE --------------
[junit4] 2> 848804 INFO (TEST-TestComputePlanAction.testNodeAdded-seed#[9705E427D041289D]) [ ] o.a.s.c.a.s.TestComputePlanAction * Node values: {
[junit4] 2> "127.0.0.1:10001_solr":{
[junit4] 2> "sysprop.java.vendor":"Oracle Corporation",
[junit4] 2> "cores":2,
[junit4] 2> "host":"127.0.0.1",
[junit4] 2> "freedisk":960,
[junit4] 2> "sysprop.java.version":"1.8.0_144",
[junit4] 2> "ip_1":"127",
[junit4] 2> "ip_3":"0",
[junit4] 2> "ip_2":"0",
[junit4] 2> "ip_4":"1",
[junit4] 2> "node":"127.0.0.1:10001
[...truncated too long message...]
Executor-7526-thread-1) [n:127.0.0.1:35901_solr c:testcollection s:shard2 r:core_node8 x:testcollection_shard2_replica_n6] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.testcollection.shard2.leader, tag=539969667
[junit4] 2> 1981022 INFO (coreCloseExecutor-7526-thread-2) [n:127.0.0.1:35901_solr c:testcollection s:shard1 r:core_node5 x:testcollection_shard1_replica_n2] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.testcollection.shard1.replica_n2, tag=1194525713
[junit4] 2> 1981022 INFO (coreCloseExecutor-7526-thread-2) [n:127.0.0.1:35901_solr c:testcollection s:shard1 r:core_node5 x:testcollection_shard1_replica_n2] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@17f72e19: rootName = solr_35901, domain = solr.core.testcollection.shard1.replica_n2, service url = null, agent id = null] for registry solr.core.testcollection.shard1.replica_n2 / com.codahale.metrics.MetricRegistry@1dac566b
[junit4] 2> 1981026 INFO (coreCloseExecutor-7525-thread-1) [n:127.0.0.1:40129_solr c:testcollection s:shard2 r:core_node7 x:testcollection_shard2_replica_n4] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.testcollection.shard2.leader, tag=1721056170
[junit4] 2> 1981026 INFO (coreCloseExecutor-7525-thread-2) [n:127.0.0.1:40129_solr c:testcollection s:shard1 r:core_node3 x:testcollection_shard1_replica_n1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.testcollection.shard1.leader, tag=1640779879
[junit4] 2> 1981027 INFO (jetty-closer-3684-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@21cdc0f0{/solr,null,UNAVAILABLE}
[junit4] 2> 1981031 INFO (coreCloseExecutor-7526-thread-2) [n:127.0.0.1:35901_solr c:testcollection s:shard1 r:core_node5 x:testcollection_shard1_replica_n2] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.testcollection.shard1.leader, tag=1194525713
[junit4] 2> 1981032 INFO (jetty-closer-3684-thread-1) [ ] o.a.s.c.Overseer Overseer (id=99303564261851142-127.0.0.1:35901_solr-n_0000000000) closing
[junit4] 2> 1981032 INFO (OverseerStateUpdate-99303564261851142-127.0.0.1:35901_solr-n_0000000000) [n:127.0.0.1:35901_solr ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:35901_solr
[junit4] 2> 1981033 WARN (OverseerAutoScalingTriggerThread-99303564261851142-127.0.0.1:35901_solr-n_0000000000) [n:127.0.0.1:35901_solr ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting.
[junit4] 2> 1981035 INFO (jetty-closer-3684-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@781726e7{/solr,null,UNAVAILABLE}
[junit4] 2> 1981035 ERROR (SUITE-TestAuthenticationFramework-seed#[9705E427D041289D]-worker) [ ] o.a.z.s.ZooKeeperServer ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes
[junit4] 2> 1981036 INFO (SUITE-TestAuthenticationFramework-seed#[9705E427D041289D]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:34101 34101
[junit4] 2> 1981511 INFO (Thread-5689) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:34101 34101
[junit4] 2> 1981512 WARN (Thread-5689) [ ] o.a.s.c.ZkTestServer Watch limit violations:
[junit4] 2> Maximum concurrent create/delete watches above limit:
[junit4] 2>
[junit4] 2> 4 /solr/configs/solrCloudCollectionConfig
[junit4] 2> 3 /solr/aliases.json
[junit4] 2> 3 /solr/clusterprops.json
[junit4] 2> 2 /solr/security.json
[junit4] 2>
[junit4] 2> Maximum concurrent data watches above limit:
[junit4] 2>
[junit4] 2> 19 /solr/collections/testcollection/state.json
[junit4] 2> 3 /solr/clusterstate.json
[junit4] 2>
[junit4] 2> Maximum concurrent children watches above limit:
[junit4] 2>
[junit4] 2> 3 /solr/live_nodes
[junit4] 2> 3 /solr/collections
[junit4] 2>
[junit4] 2> NOTE: leaving temporary files on disk at: /home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J1/temp/solr.cloud.TestAuthenticationFramework_9705E427D041289D-001
[junit4] 2> Jan 06, 2018 3:22:29 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks
[junit4] 2> WARNING: Will linger awaiting termination of 1 leaked thread(s).
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene70): {_version_=PostingsFormat(name=LuceneVarGapFixedInterval), id=PostingsFormat(name=Memory)}, docValues:{_version_=DocValuesFormat(name=Lucene70)}, maxPointsInLeafNode=222, maxMBSortInHeap=7.473316188855817, sim=Asserting(org.apache.lucene.search.similarities.AssertingSimilarity@7008c249), locale=nn-NO, timezone=Australia/Victoria
[junit4] 2> NOTE: Linux 4.10.0-40-generic amd64/Oracle Corporation 1.8.0_144 (64-bit)/cpus=8,threads=1,free=248944624,total=518979584
[junit4] 2> NOTE: All tests run in this JVM: [TestPerFieldSimilarityWithDefaultOverride, HdfsRestartWhileUpdatingTest, RestartWhileUpdatingTest, TestDistribIDF, TestCloudPseudoReturnFields, ZkSolrClientTest, TestFieldCacheSortRandom, TestStressLucene, TestBM25SimilarityFactory, TestManagedSchemaThreadSafety, LeaderInitiatedRecoveryOnShardRestartTest, TestUninvertingReader, TestPolicyCloud, DeleteShardTest, TestRemoteStreaming, TestLegacyFieldCache, DirectUpdateHandlerTest, CloudExitableDirectoryReaderTest, SolrIndexMetricsTest, TestClassicSimilarityFactory, TestHalfAndHalfDocValues, SearchRateTriggerTest, NotRequiredUniqueKeyTest, TestLegacyField, DistributedFacetPivotSmallTest, PreAnalyzedFieldTest, AddReplicaTest, UninvertDocValuesMergePolicyTest, TestCoreBackup, TestNRTOpen, SearchHandlerTest, DistributedVersionInfoTest, ShardRoutingTest, MetricTriggerTest, TestAnalyzedSuggestions, TestDocumentBuilder, JvmMetricsTest, StatsReloadRaceTest, TestImplicitCoreProperties, SampleTest, NumericFieldsTest, TestDistribStateManager, SynonymTokenizerTest, SpatialHeatmapFacetsTest, CdcrReplicationDistributedZkTest, TestFieldSortValues, CdcrUpdateLogTest, LukeRequestHandlerTest, TestNestedDocsSort, OutOfBoxZkACLAndCredentialsProvidersTest, DistributedQueryComponentOptimizationTest, TestPayloadScoreQParserPlugin, QueryEqualityTest, TestCorePropertiesReload, TestPerFieldSimilarity, TestPivotHelperCode, MissingSegmentRecoveryTest, TestNumericRangeQuery64, CoreMergeIndexesAdminHandlerTest, TestMaxTokenLenTokenizer, TestLRUStatsCache, TestRebalanceLeaders, TestRequestStatusCollectionAPI, TestSchemaVersionResource, TestMaxScoreQueryParser, TestUtilizeNode, SpellingQueryConverterTest, TestFieldResource, BlockJoinFacetSimpleTest, BaseCdcrDistributedZkTest, TestSQLHandlerNonCloud, TestNamedUpdateProcessors, AnalyticsMergeStrategyTest, DistribDocExpirationUpdateProcessorTest, DistributedIntervalFacetingTest, OpenCloseCoreStressTest, AutoscalingHistoryHandlerTest, HdfsChaosMonkeyNothingIsSafeTest, TestConfigSetImmutable, UUIDUpdateProcessorFallbackTest, TestDistributedStatsComponentCardinality, SuggesterFSTTest, TestReqParamsAPI, TestSchemaNameResource, DistributedTermsComponentTest, TestFileDictionaryLookup, ShardRoutingCustomTest, TestImpersonationWithHadoopAuth, TestMinMaxOnMultiValuedField, TestJavabinTupleStreamParser, ClassificationUpdateProcessorIntegrationTest, DistributedDebugComponentTest, CollectionTooManyReplicasTest, TestNoOpRegenerator, UpdateLogTest, TestComplexPhraseLeadingWildcard, TestShortCircuitedRequests, SpellCheckCollatorWithCollapseTest, DocValuesMultiTest, RulesTest, CdcrVersionReplicationTest, TestFieldCache, PropertiesRequestHandlerTest, PolyFieldTest, MoveReplicaTest, BlockCacheTest, DebugComponentTest, SolrShardReporterTest, HighlighterMaxOffsetTest, SimpleCollectionCreateDeleteTest, TestAtomicUpdateErrorCases, DOMUtilTest, TestStressRecovery, TestSimpleTrackingShardHandler, SolrXmlInZkTest, MBeansHandlerTest, DistributedFacetSimpleRefinementLongTailTest, PingRequestHandlerTest, LargeFieldTest, TestDocSet, OpenExchangeRatesOrgProviderTest, SchemaVersionSpecificBehaviorTest, TestMacroExpander, ChaosMonkeySafeLeaderTest, UnloadDistributedZkTest, CollectionsAPIDistributedZkTest, SyncSliceTest, BasicZkTest, ClusterStateUpdateTest, TestRandomFaceting, TestRandomDVFaceting, ZkCLITest, TestDistributedGrouping, TestFaceting, TestRecovery, DistributedSpellCheckComponentTest, TermVectorComponentDistributedTest, TestStressReorder, TestJoin, TestReload, TestStressVersions, TestRangeQuery, SolrIndexSplitterTest, SignatureUpdateProcessorFactoryTest, CoreAdminHandlerTest, SuggesterTSTTest, TestTrie, NoCacheHeaderTest, TestUpdate, DefaultValueUpdateProcessorTest, StatelessScriptUpdateProcessorFactoryTest, CacheHeaderTest, TestWriterPerf, PrimitiveFieldTypeTest, TestOmitPositions, PathHierarchyTokenizerFactoryTest, TestSolrQueryParser, SolrPluginUtilsTest, TestCollationField, TestCSVResponseWriter, TestPHPSerializedResponseWriter, HighlighterConfigTest, SOLR749Test, TestQuerySenderNoQuery, ResponseLogComponentTest, TestMergePolicyConfig, TestFuzzyAnalyzedSuggestions, DirectSolrConnectionTest, SpellPossibilityIteratorTest, TestXIncludeConfig, TestSweetSpotSimilarityFactory, TestDFRSimilarityFactory, TestFastWriter, ScriptEngineTest, PluginInfoTest, ChaosMonkeyNothingIsSafeTest, AssignTest, AsyncCallRequestStatusResponseTest, ChaosMonkeyNothingIsSafeWithPullReplicasTest, CollectionStateFormat2Test, ConcurrentDeleteAndCreateCollectionTest, ConfigSetsAPITest, CreateCollectionCleanupTest, DeleteLastCustomShardedReplicaTest, DeleteNodeTest, DistribCursorPagingTest, HealthCheckHandlerTest, HttpPartitionTest, LegacyCloudClusterPropTest, MoveReplicaHDFSTest, SaslZkACLProviderTest, SharedFSAutoReplicaFailoverTest, SolrCLIZkUtilsTest, SolrCloudExampleTest, TestAuthenticationFramework]
[junit4] Completed [510/766 (2!)] on J1 in 9.95s, 1 test, 1 error <<< FAILURES!
[...truncated 48979 lines...]