Jira's down for maintence, so i can't report this in jira, but... These TestClusterStateProvider.testAutoScalingConfig failures seem to reproduce fairly reliably for me -- across both master and branch_7x. Attempting to generate new seeds I've never seen this test pass.
Picking one seed at random, and using git bisect starting at when this test seems to have landed in master points to SOLR-11063 as being the culprit that broke it... hossman@tray:~/lucene/alt_dev [master] $ git bisect start HEAD d6d2e3b2e30b600b9f550abf9414743d628cbcf0 Bisecting: 60 revisions left to test after this (roughly 6 steps) [a56cb42fde41422c99108ff2749c29080bb94e36] LUCENE-8012: LTR contrib needs to use float values in explanations hossman@tray:~/lucene/alt_dev [detached] $ git bisect run sh -c 'ant clean && cd solr/core/ && ant test -Dtestcase=TestClusterStateProvider -Dtests.method=testAutoScalingConfig -Dtests.seed=893E46D2E59F76F2 -Dtests.slow=true -Dtests.locale=ca-ES -Dtests.timezone=Indian/Cocos -Dtests.asserts=true -Dtests.file.encoding=UTF-8' running sh -c ant clean && cd solr/core/ && ant test -Dtestcase=TestClusterStateProvider -Dtests.method=testAutoScalingConfig -Dtests.seed=893E46D2E59F76F2 -Dtests.slow=true -D ... fe86ab982d14b02d5fc9842259f9d0ae1a949757 is the first bad commit commit fe86ab982d14b02d5fc9842259f9d0ae1a949757 Author: Noble Paul <[email protected]> Date: Fri Jan 12 23:48:30 2018 +1100 SOLR-11063: Suggesters should accept required freedisk as a hint :040000 040000 b0f02f132700bcf948cc0a9c18d6d6772cdfa792 7a2a8b9242da48cce64003a6f2ff942c2cb8859b M solr bisect run success : FAILED: org.apache.solr.cloud.autoscaling.sim.TestClusterStateProvider.testAutoScalingConfig : : Error Message: : expected: org.apache.solr.client.solrj.cloud.autoscaling.AutoScalingConfig<{ "cluster-preferences":[{"maximize":"freedisk"}], "triggers":{".auto_add_replicas":{ "name":".auto_add_replicas", "event":"nodeLost", "waitFor":30, "actions":[ { "name":"auto_add_replicas_plan", "class":"solr.AutoAddReplicasPlanAction"}, { "name":"execute_plan", "class":"solr.ExecutePlanAction"}], "enabled":true}}, "listeners":{".auto_add_replicas.system":{ "trigger":".auto_add_replicas", "afterAction":[], "stage":[ "STARTED", "ABORTED", "SUCCEEDED", "FAILED", "BEFORE_ACTION", "AFTER_ACTION", "IGNORED"], "class":"org.apache.solr.cloud.autoscaling.SystemLogListener", "beforeAction":[]}}, "properties":{}}> but was: org.apache.solr.client.solrj.cloud.autoscaling.AutoScalingConfig<{ "cluster-preferences":[{"maximize":"freedisk"}], "triggers":{".auto_add_replicas":{ "name":".auto_add_replicas", "event":"nodeLost", "waitFor":30, "actions":[ { "name":"auto_add_replicas_plan", "class":"solr.AutoAddReplicasPlanAction"}, { "name":"execute_plan", "class":"solr.ExecutePlanAction"}], "enabled":true}}, "listeners":{".auto_add_replicas.system":{ "trigger":".auto_add_replicas", "afterAction":[], "stage":[ "STARTED", "ABORTED", "SUCCEEDED", "FAILED", "BEFORE_ACTION", "AFTER_ACTION", "IGNORED"], "class":"org.apache.solr.cloud.autoscaling.SystemLogListener", "beforeAction":[]}}, "properties":{}}> : : Stack Trace: : java.lang.AssertionError: expected: org.apache.solr.client.solrj.cloud.autoscaling.AutoScalingConfig<{ : "cluster-preferences":[{"maximize":"freedisk"}], : "triggers":{".auto_add_replicas":{ : "name":".auto_add_replicas", : "event":"nodeLost", : "waitFor":30, : "actions":[ : { : "name":"auto_add_replicas_plan", : "class":"solr.AutoAddReplicasPlanAction"}, : { : "name":"execute_plan", : "class":"solr.ExecutePlanAction"}], : "enabled":true}}, : "listeners":{".auto_add_replicas.system":{ : "trigger":".auto_add_replicas", : "afterAction":[], : "stage":[ : "STARTED", : "ABORTED", : "SUCCEEDED", : "FAILED", : "BEFORE_ACTION", : "AFTER_ACTION", : "IGNORED"], : "class":"org.apache.solr.cloud.autoscaling.SystemLogListener", : "beforeAction":[]}}, : "properties":{}}> but was: org.apache.solr.client.solrj.cloud.autoscaling.AutoScalingConfig<{ : "cluster-preferences":[{"maximize":"freedisk"}], : "triggers":{".auto_add_replicas":{ : "name":".auto_add_replicas", : "event":"nodeLost", : "waitFor":30, : "actions":[ : { : "name":"auto_add_replicas_plan", : "class":"solr.AutoAddReplicasPlanAction"}, : { : "name":"execute_plan", : "class":"solr.ExecutePlanAction"}], : "enabled":true}}, : "listeners":{".auto_add_replicas.system":{ : "trigger":".auto_add_replicas", : "afterAction":[], : "stage":[ : "STARTED", : "ABORTED", : "SUCCEEDED", : "FAILED", : "BEFORE_ACTION", : "AFTER_ACTION", : "IGNORED"], : "class":"org.apache.solr.cloud.autoscaling.SystemLogListener", : "beforeAction":[]}}, : "properties":{}}> : at __randomizedtesting.SeedInfo.seed([607345A73B2456EA:5FFB460F2C72A60D]:0) : at org.junit.Assert.fail(Assert.java:93) : at org.junit.Assert.failNotEquals(Assert.java:647) : at org.junit.Assert.assertEquals(Assert.java:128) : at org.junit.Assert.assertEquals(Assert.java:147) : at org.apache.solr.cloud.autoscaling.sim.TestClusterStateProvider.testAutoScalingConfig(TestClusterStateProvider.java:214) : 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) : : : : : Build Log: : [...truncated 12344 lines...] : [junit4] Suite: org.apache.solr.cloud.TestSolrCloudWithSecureImpersonation : [junit4] 2> 833200 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[607345A73B2456EA]-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_607345A73B2456EA-001/init-core-data-001 : [junit4] 2> 833201 WARN (SUITE-TestSolrCloudWithSecureImpersonation-seed#[607345A73B2456EA]-worker) [ ] o.a.s.SolrTestCaseJ4 startTrackingSearchers: numOpens=2420 numCloses=2420 : [junit4] 2> 833201 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[607345A73B2456EA]-worker) [ ] o.a.s.SolrTestCaseJ4 Using TrieFields (NUMERIC_POINTS_SYSPROP=false) w/NUMERIC_DOCVALUES_SYSPROP=true : [junit4] 2> 833202 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[607345A73B2456EA]-worker) [ ] o.a.s.SolrTestCaseJ4 Randomized ssl (true) and clientAuth (true) via: @org.apache.solr.util.RandomizeSSL(reason=, ssl=NaN, value=NaN, clientAuth=NaN) : [junit4] 2> 833214 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[607345A73B2456EA]-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_607345A73B2456EA-001/tempDir-001 : [junit4] 2> 833214 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[607345A73B2456EA]-worker) [ ] o.a.s.c.ZkTestServer STARTING ZK TEST SERVER : [junit4] 2> 833214 INFO (Thread-1960) [ ] o.a.s.c.ZkTestServer client port:0.0.0.0/0.0.0.0:0 : [junit4] 2> 833214 INFO (Thread-1960) [ ] o.a.s.c.ZkTestServer Starting server : [junit4] 2> 833215 ERROR (Thread-1960) [ ] 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> 833314 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[607345A73B2456EA]-worker) [ ] o.a.s.c.ZkTestServer start zk server on port:45301 : [junit4] 2> 833316 INFO (zkConnectionManagerCallback-1348-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected : [junit4] 2> 833318 INFO (jetty-launcher-1345-thread-1) [ ] o.e.j.s.Server jetty-9.3.20.v20170531 : [junit4] 2> 833318 INFO (jetty-launcher-1345-thread-2) [ ] o.e.j.s.Server jetty-9.3.20.v20170531 : [junit4] 2> 833319 INFO (jetty-launcher-1345-thread-1) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@19b199e{/solr,null,AVAILABLE} : [junit4] 2> 833319 INFO (jetty-launcher-1345-thread-2) [ ] o.e.j.s.h.ContextHandler Started o.e.j.s.ServletContextHandler@7870{/solr,null,AVAILABLE} : [junit4] 2> 833322 INFO (jetty-launcher-1345-thread-1) [ ] o.e.j.s.AbstractConnector Started ServerConnector@1c41bd6{SSL,[ssl, http/1.1]}{127.0.0.1:44219} : [junit4] 2> 833322 INFO (jetty-launcher-1345-thread-2) [ ] o.e.j.s.AbstractConnector Started ServerConnector@1410f10{SSL,[ssl, http/1.1]}{127.0.0.1:40941} : [junit4] 2> 833322 INFO (jetty-launcher-1345-thread-1) [ ] o.e.j.s.Server Started @834929ms : [junit4] 2> 833322 INFO (jetty-launcher-1345-thread-2) [ ] o.e.j.s.Server Started @834929ms : [junit4] 2> 833322 INFO (jetty-launcher-1345-thread-1) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=44219} : [junit4] 2> 833322 INFO (jetty-launcher-1345-thread-2) [ ] o.a.s.c.s.e.JettySolrRunner Jetty properties: {hostContext=/solr, hostPort=40941} : [junit4] 2> 833322 ERROR (jetty-launcher-1345-thread-2) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. : [junit4] 2> 833322 ERROR (jetty-launcher-1345-thread-1) [ ] o.a.s.u.StartupLoggingUtils Missing Java Option solr.log.dir. Logging may be missing or incomplete. : [junit4] 2> 833323 INFO (jetty-launcher-1345-thread-2) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 8.0.0 : [junit4] 2> 833323 INFO (jetty-launcher-1345-thread-1) [ ] o.a.s.s.SolrDispatchFilter ___ _ Welcome to Apache Solr? version 8.0.0 : [junit4] 2> 833323 INFO (jetty-launcher-1345-thread-2) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null : [junit4] 2> 833323 INFO (jetty-launcher-1345-thread-1) [ ] o.a.s.s.SolrDispatchFilter / __| ___| |_ _ Starting in cloud mode on port null : [junit4] 2> 833323 INFO (jetty-launcher-1345-thread-2) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null : [junit4] 2> 833323 INFO (jetty-launcher-1345-thread-1) [ ] o.a.s.s.SolrDispatchFilter \__ \/ _ \ | '_| Install dir: null : [junit4] 2> 833323 INFO (jetty-launcher-1345-thread-2) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-01-14T20:12:10.827Z : [junit4] 2> 833323 INFO (jetty-launcher-1345-thread-1) [ ] o.a.s.s.SolrDispatchFilter |___/\___/_|_| Start time: 2018-01-14T20:12:10.827Z : [junit4] 2> 833327 INFO (zkConnectionManagerCallback-1351-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected : [junit4] 2> 833327 INFO (zkConnectionManagerCallback-1352-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected : [junit4] 2> 833327 INFO (jetty-launcher-1345-thread-1) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... : [junit4] 2> 833327 INFO (jetty-launcher-1345-thread-2) [ ] o.a.s.s.SolrDispatchFilter solr.xml found in ZooKeeper. Loading... : [junit4] 2> 833336 INFO (jetty-launcher-1345-thread-2) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:45301/solr : [junit4] 2> 833336 INFO (jetty-launcher-1345-thread-1) [ ] o.a.s.c.ZkContainer Zookeeper client=127.0.0.1:45301/solr : [junit4] 2> 833337 INFO (zkConnectionManagerCallback-1358-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected : [junit4] 2> 833337 INFO (zkConnectionManagerCallback-1360-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected : [junit4] 2> 833337 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 0x160f64d045f0004, 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> 833338 INFO (zkConnectionManagerCallback-1363-thread-1-processing-n:127.0.0.1:44219_solr) [n:127.0.0.1:44219_solr ] o.a.s.c.c.ConnectionManager zkClient has connected : [junit4] 2> 833338 INFO (zkConnectionManagerCallback-1364-thread-1-processing-n:127.0.0.1:40941_solr) [n:127.0.0.1:40941_solr ] o.a.s.c.c.ConnectionManager zkClient has connected : [junit4] 2> 833368 INFO (jetty-launcher-1345-thread-2) [n:127.0.0.1:40941_solr ] o.a.s.c.Overseer Overseer (id=null) closing : [junit4] 2> 833368 INFO (jetty-launcher-1345-thread-1) [n:127.0.0.1:44219_solr ] o.a.s.c.Overseer Overseer (id=null) closing : [junit4] 2> 833369 INFO (jetty-launcher-1345-thread-2) [n:127.0.0.1:40941_solr ] o.a.s.c.OverseerElectionContext I am going to be the leader 127.0.0.1:40941_solr : [junit4] 2> 833369 INFO (jetty-launcher-1345-thread-1) [n:127.0.0.1:44219_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44219_solr : [junit4] 2> 833369 INFO (jetty-launcher-1345-thread-2) [n:127.0.0.1:40941_solr ] o.a.s.c.Overseer Overseer (id=99350002448400390-127.0.0.1:40941_solr-n_0000000000) starting : [junit4] 2> 833369 INFO (zkCallback-1362-thread-1-processing-n:127.0.0.1:40941_solr) [n:127.0.0.1:40941_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) : [junit4] 2> 833370 INFO (zkCallback-1361-thread-1-processing-n:127.0.0.1:44219_solr) [n:127.0.0.1:44219_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (1) : [junit4] 2> 833373 INFO (jetty-launcher-1345-thread-2) [n:127.0.0.1:40941_solr ] o.a.s.c.ZkController Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40941_solr : [junit4] 2> 833374 INFO (zkCallback-1361-thread-1-processing-n:127.0.0.1:44219_solr) [n:127.0.0.1:44219_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) : [junit4] 2> 833374 INFO (zkCallback-1362-thread-1-processing-n:127.0.0.1:40941_solr) [n:127.0.0.1:40941_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (2) : [junit4] 2> 833498 INFO (jetty-launcher-1345-thread-1) [n:127.0.0.1:44219_solr ] o.a.s.c.CoreContainer Initializing authentication plugin: org.apache.solr.security.HttpParamDelegationTokenPlugin : [junit4] 2> 833502 WARN (jetty-launcher-1345-thread-1) [n:127.0.0.1:44219_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> 833506 INFO (jetty-launcher-1345-thread-1) [n:127.0.0.1:44219_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-mana ger.enable=true, solr.kerberos.impersonator.user.wrongHost.groups=*, kerberos.name.rules=DEFAULT, signer.secret.provider=zookeeper, solr.kerberos.impersonator.user.anyHostUsersGroup.hosts=*} : [junit4] 2> 833541 INFO (jetty-launcher-1345-thread-2) [n:127.0.0.1:40941_solr ] o.a.s.c.CoreContainer Initializing authentication plugin: org.apache.solr.security.HttpParamDelegationTokenPlugin : [junit4] 2> 833541 WARN (jetty-launcher-1345-thread-2) [n:127.0.0.1:40941_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> 833541 INFO (jetty-launcher-1345-thread-2) [n:127.0.0.1:40941_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-mana ger.enable=true, solr.kerberos.impersonator.user.wrongHost.groups=*, kerberos.name.rules=DEFAULT, signer.secret.provider=zookeeper, solr.kerberos.impersonator.user.anyHostUsersGroup.hosts=*} : [junit4] 2> 833562 INFO (jetty-launcher-1345-thread-2) [n:127.0.0.1:40941_solr ] o.a.c.f.i.CuratorFrameworkImpl Starting : [junit4] 2> 833562 INFO (jetty-launcher-1345-thread-1) [n:127.0.0.1:44219_solr ] o.a.c.f.i.CuratorFrameworkImpl Starting : [junit4] 2> 833576 INFO (jetty-launcher-1345-thread-1-EventThread) [n:127.0.0.1:44219_solr ] o.a.c.f.s.ConnectionStateManager State change: CONNECTED : [junit4] 2> 833576 INFO (jetty-launcher-1345-thread-2-EventThread) [n:127.0.0.1:40941_solr ] o.a.c.f.s.ConnectionStateManager State change: CONNECTED : [junit4] 2> 833644 WARN (jetty-launcher-1345-thread-1) [n:127.0.0.1:44219_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> 833644 WARN (jetty-launcher-1345-thread-2) [n:127.0.0.1:40941_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> 833676 INFO (jetty-launcher-1345-thread-1) [n:127.0.0.1:44219_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_44219.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@cc1628 : [junit4] 2> 833677 INFO (jetty-launcher-1345-thread-2) [n:127.0.0.1:40941_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_40941.solr.node' (registry 'solr.node') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@cc1628 : [junit4] 2> 833684 INFO (jetty-launcher-1345-thread-1) [n:127.0.0.1:44219_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_44219.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@cc1628 : [junit4] 2> 833684 INFO (jetty-launcher-1345-thread-1) [n:127.0.0.1:44219_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_44219.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@cc1628 : [junit4] 2> 833685 INFO (jetty-launcher-1345-thread-1) [n:127.0.0.1:44219_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_607345A73B2456EA-001/tempDir-001/node1/. : [junit4] 2> 833686 INFO (jetty-launcher-1345-thread-2) [n:127.0.0.1:40941_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_40941.solr.jvm' (registry 'solr.jvm') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@cc1628 : [junit4] 2> 833686 INFO (jetty-launcher-1345-thread-2) [n:127.0.0.1:40941_solr ] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_40941.solr.jetty' (registry 'solr.jetty') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@cc1628 : [junit4] 2> 833687 INFO (jetty-launcher-1345-thread-2) [n:127.0.0.1:40941_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_607345A73B2456EA-001/tempDir-001/node2/. : [junit4] 2> 833725 INFO (zkConnectionManagerCallback-1370-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected : [junit4] 2> 833735 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyNoConfigGroups-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyNoConfigGroups : [junit4] 2> 833784 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyNoConfigGroups-seed#[607345A73B2456EA]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=noGroups&p=noGroups&t=test&e=1515996731275&s=r5PNXDpWhqFdK6ivqVFRSzQ0JQ8="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:11 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:11 GMT : [junit4] 2> 833785 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyNoConfigGroups-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyNoConfigGroups : [junit4] 2> 833795 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyWrongHost-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyWrongHost : [junit4] 2> 839013 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyWrongHost-seed#[607345A73B2456EA]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=wrongHost&p=wrongHost&t=test&e=1515996731299&s=Nj/wxDF18s56Os3pCRy1hZaMgNg="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:11 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:11 GMT : [junit4] 2> 839014 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyWrongHost-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyWrongHost : [junit4] 2> 839030 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateHost-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyValidateHost : [junit4] 2> 839034 INFO (qtp9631235-7172) [n:127.0.0.1:40941_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> 839034 INFO (qtp9631235-7172) [n:127.0.0.1:40941_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> 839034 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateHost-seed#[607345A73B2456EA]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=localHostAnyGroup&p=localHostAnyGroup&t=test&e=1515996736535&s=GvjxvsvNTp+JnnsjIQ6/3rwppOw="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:16 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:16 GMT : [junit4] 2> 839034 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateHost-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyValidateHost : [junit4] 2> 839044 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyNoConfigHosts-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyNoConfigHosts : [junit4] 2> 839046 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyNoConfigHosts-seed#[607345A73B2456EA]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=noHosts&p=noHosts&t=test&e=1515996736549&s=p7KCygViyWK2/NVnnwUL1sNFQWc="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:16 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:16 GMT : [junit4] 2> 839047 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyNoConfigHosts-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyNoConfigHosts : [junit4] 2> 839056 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateAnyHostAnyUser-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyValidateAnyHostAnyUser : [junit4] 2> 839056 INFO (qtp9631235-7160) [n:127.0.0.1:40941_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> 839056 INFO (qtp9631235-7160) [n:127.0.0.1:40941_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> 839057 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateAnyHostAnyUser-seed#[607345A73B2456EA]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=anyHostAnyUser&p=anyHostAnyUser&t=test&e=1515996736560&s=EKfjYIxpM5wXFVKn8OjSTYKjT6A="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:16 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:16 GMT : [junit4] 2> 839057 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateAnyHostAnyUser-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyValidateAnyHostAnyUser : [junit4] 2> 839065 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidRemote-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyInvalidRemote : [junit4] 2> 839069 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidRemote-seed#[607345A73B2456EA]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=localHostAnyGroup&p=localHostAnyGroup&t=test&e=1515996736569&s=rXAXy6lRq9tjZ/cAhNPgXoN36N0="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:16 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:16 GMT : [junit4] 2> 839070 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidRemote-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyInvalidRemote : [junit4] 2> 839079 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyUnknownRemote-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyUnknownRemote : [junit4] 2> 850729 WARN (jetty-launcher-1345-thread-1-SendThread(127.0.0.1:45301)) [n:127.0.0.1:44219_solr ] o.a.z.ClientCnxn Client session timed out, have not heard from server in 17044ms for sessionid 0x160f64d045f0005 : [junit4] 2> 850729 WARN (jetty-launcher-1345-thread-1-SendThread(127.0.0.1:45301)) [n:127.0.0.1:44219_solr ] o.a.z.ClientCnxn Client session timed out, have not heard from server in 17088ms for sessionid 0x160f64d045f0008 : [junit4] 2> 850729 WARN (jetty-launcher-1345-thread-2-SendThread(127.0.0.1:45301)) [n:127.0.0.1:40941_solr ] o.a.z.ClientCnxn Client session timed out, have not heard from server in 17088ms for sessionid 0x160f64d045f0007 : [junit4] 2> 850729 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 0x160f64d045f0008, 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> 850730 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 0x160f64d045f0005, 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> 850730 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 0x160f64d045f0007, 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> 850731 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyUnknownRemote-seed#[607345A73B2456EA]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=localHostAnyGroup&p=localHostAnyGroup&t=test&e=1515996736583&s=dfmuzR/I2V4b/aD/BcZkvv6i/TU="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:16 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:16 GMT : [junit4] 2> 850731 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyUnknownRemote-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyUnknownRemote : [junit4] 2> 850743 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidGroup-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyInvalidGroup : [junit4] 2> 850754 WARN (qtp9631235-7174) [ ] 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> 850756 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidGroup-seed#[607345A73B2456EA]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=bogusGroup&p=bogusGroup&t=test&e=1515996748247&s=GPRjGGItE1UyIIwdYDtH4BjZtHw="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:28 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:28 GMT : [junit4] 2> 850756 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidGroup-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyInvalidGroup : [junit4] 2> 850767 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateGroup-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyValidateGroup : [junit4] 2> 850788 INFO (qtp9631235-7160) [n:127.0.0.1:40941_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> 850788 INFO (qtp9631235-7160) [n:127.0.0.1:40941_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> 850788 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateGroup-seed#[607345A73B2456EA]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=anyHostUsersGroup&p=anyHostUsersGroup&t=test&e=1515996748272&s=z9W6+Z/X8M+3wJWuCDoy3HgbeQU="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:28 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:28 GMT : [junit4] 2> 850788 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyValidateGroup-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyValidateGroup : [junit4] 2> 850799 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidProxyUser-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyInvalidProxyUser : [junit4] 2> 850801 WARN (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidProxyUser-seed#[607345A73B2456EA]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=bar&p=bar&t=test&e=1515996748303&s=SbEbEsOm7jevbmKVudIKWskVYVI="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:28 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:28 GMT : [junit4] 2> 850801 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyInvalidProxyUser-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyInvalidProxyUser : [junit4] 2> 850814 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyNullProxyUser-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testProxyNullProxyUser : [junit4] 2> 850814 INFO (qtp9631235-7172) [n:127.0.0.1:40941_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:449) : [junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:349) : [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.ssl.SslConnection.onFillable(SslConnection.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> 850815 WARN (qtp9631235-7172) [n:127.0.0.1:40941_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:455) : [junit4] 2> at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:349) : [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.ssl.SslConnection.onFillable(SslConnection.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:449) : [junit4] 2> ... 29 more : [junit4] 2> 850816 INFO (TEST-TestSolrCloudWithSecureImpersonation.testProxyNullProxyUser-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testProxyNullProxyUser : [junit4] 2> 850829 INFO (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Starting testForwarding : [junit4] 2> 850830 INFO (jetty-launcher-1345-thread-1-EventThread) [n:127.0.0.1:44219_solr ] o.a.c.f.s.ConnectionStateManager State change: SUSPENDED : [junit4] 2> 850830 WARN (zkConnectionManagerCallback-1363-thread-1-processing-n:127.0.0.1:44219_solr) [n:127.0.0.1:44219_solr ] o.a.s.c.c.ConnectionManager Watcher org.apache.solr.common.cloud.ConnectionManager@11c0caf name: ZooKeeperConnection Watcher:127.0.0.1:45301/solr got event WatchedEvent state:Disconnected type:None path:null path: null type: None : [junit4] 2> 850830 WARN (zkConnectionManagerCallback-1363-thread-1-processing-n:127.0.0.1:44219_solr) [n:127.0.0.1:44219_solr ] o.a.s.c.c.ConnectionManager zkClient has disconnected : [junit4] 2> 850835 INFO (zkConnectionManagerCallback-1373-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected : [junit4] 2> 851090 INFO (zkConnectionManagerCallback-1376-thread-1) [ ] o.a.s.c.c.ConnectionManager zkClient has connected : [junit4] 2> 851091 INFO (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[607345A73B2456EA]) [ ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (0) -> (2) : [junit4] 2> 851092 INFO (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[607345A73B2456EA]) [ ] o.a.s.c.s.i.ZkClientClusterStateProvider Cluster at 127.0.0.1:45301/solr ready : [junit4] 2> 851094 INFO (qtp9631235-7172) [n:127.0.0.1:40941_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> 851095 INFO (OverseerThreadFactory-3228-thread-1-processing-n:127.0.0.1:40941_solr) [n:127.0.0.1:40941_solr ] o.a.s.c.CreateCollectionCmd Create collection forwardingCollection : [junit4] 2> 851213 INFO (OverseerStateUpdate-99350002448400390-127.0.0.1:40941_solr-n_0000000000) [n:127.0.0.1:40941_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":"https://127.0.0.1:40941/solr";, : [junit4] 2> "type":"NRT", : [junit4] 2> "waitForFinalState":"false"} : [junit4] 2> 851340 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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> 851340 INFO (qtp9631235-7170) [n:127.0.0.1:40941_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores : [junit4] 2> 851443 INFO (zkCallback-1362-thread-1-processing-n:127.0.0.1:40941_solr) [n:127.0.0.1:40941_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> 851443 INFO (zkCallback-1362-thread-2-processing-n:127.0.0.1:40941_solr) [n:127.0.0.1:40941_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> 851943 INFO (jetty-launcher-1345-thread-2-EventThread) [n:127.0.0.1:40941_solr ] o.a.c.f.s.ConnectionStateManager State change: SUSPENDED : [junit4] 2> 852354 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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> 852373 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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> 852499 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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> 852506 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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> 852507 INFO (qtp9631235-7170) [n:127.0.0.1:40941_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.m.r.SolrJmxReporter JMX monitoring for 'solr_40941.solr.core.forwardingCollection.shard1.replica_n1' (registry 'solr.core.forwardingCollection.shard1.replica_n1') enabled at server: com.sun.jmx.mbeanserver.JmxMBeanServer@cc1628 : [junit4] 2> 852507 INFO (qtp9631235-7170) [n:127.0.0.1:40941_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.SolrCore solr.RecoveryStrategy.Builder : [junit4] 2> 852507 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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_607345A73B2456EA-001/tempDir-001/node2/forwardingCollection_shard1_replica_n1], dataDir=[/home/jenkins/workspace/Lucene-Solr-master-Linux/solr/build/solr-core/test/J0/temp/solr.cloud.TestSolrCloudWithSecureImpersonation_607345A73B2456EA-001/tempDir-001/node2/./forwardingCollection_shard1_replica_n1/data/] : [junit4] 2> 852510 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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=14, maxMergeAtOnceExplicit=15, maxMergedSegmentMB=65.8125, floorSegmentMB=1.486328125, forceMergeDeletesPctAllowed=28.468254921113118, segmentsPerTier=41.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=0.3865847439261596 : [junit4] 2> 852539 INFO (zkConnectionManagerCallback-1363-thread-1-processing-n:127.0.0.1:44219_solr) [n:127.0.0.1:44219_solr ] o.a.s.c.c.ConnectionManager zkClient has connected : [junit4] 2> 852556 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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> 852556 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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> 852557 INFO (qtp9631235-7170) [n:127.0.0.1:40941_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.u.CommitTracker Hard AutoCommit: disabled : [junit4] 2> 852557 INFO (qtp9631235-7170) [n:127.0.0.1:40941_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.u.CommitTracker Soft AutoCommit: disabled : [junit4] 2> 852558 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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=25, maxMergeAtOnceExplicit=14, maxMergedSegmentMB=94.5517578125, floorSegmentMB=1.3544921875, forceMergeDeletesPctAllowed=17.983388940845256, segmentsPerTier=22.0, maxCFSSegmentSizeMB=1.009765625, noCFSRatio=1.0 : [junit4] 2> 852558 INFO (qtp9631235-7170) [n:127.0.0.1:40941_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@663f4a[forwardingCollection_shard1_replica_n1] main] : [junit4] 2> 852559 INFO (qtp9631235-7170) [n:127.0.0.1:40941_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.h.c.SpellCheckComponent Initializing spell checkers : [junit4] 2> 852614 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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> 852701 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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> 852701 INFO (searcherExecutor-3233-thread-1-processing-n:127.0.0.1:40941_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:40941_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> 852701 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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 1589600059606958080 : [junit4] 2> 852701 INFO (searcherExecutor-3233-thread-1-processing-n:127.0.0.1:40941_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:40941_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> 852701 INFO (searcherExecutor-3233-thread-1-processing-n:127.0.0.1:40941_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:40941_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> 852701 INFO (searcherExecutor-3233-thread-1-processing-n:127.0.0.1:40941_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:40941_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> 852702 INFO (searcherExecutor-3233-thread-1-processing-n:127.0.0.1:40941_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:40941_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> 852702 INFO (searcherExecutor-3233-thread-1-processing-n:127.0.0.1:40941_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:40941_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> 852702 INFO (searcherExecutor-3233-thread-1-processing-n:127.0.0.1:40941_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:40941_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> 852702 INFO (searcherExecutor-3233-thread-1-processing-n:127.0.0.1:40941_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:40941_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> 852702 INFO (searcherExecutor-3233-thread-1-processing-n:127.0.0.1:40941_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:40941_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> 852703 INFO (searcherExecutor-3233-thread-1-processing-n:127.0.0.1:40941_solr x:forwardingCollection_shard1_replica_n1 s:shard1 c:forwardingCollection r:core_node2) [n:127.0.0.1:40941_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@663f4a[forwardingCollection_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader())} : [junit4] 2> 852704 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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> 852704 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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> 852704 INFO (qtp9631235-7170) [n:127.0.0.1:40941_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.SyncStrategy Sync replicas to https://127.0.0.1:40941/solr/forwardingCollection_shard1_replica_n1/ : [junit4] 2> 852704 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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> 852704 INFO (qtp9631235-7170) [n:127.0.0.1:40941_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.SyncStrategy https://127.0.0.1:40941/solr/forwardingCollection_shard1_replica_n1/ has no replicas : [junit4] 2> 852704 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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> 852706 INFO (qtp9631235-7170) [n:127.0.0.1:40941_solr c:forwardingCollection s:shard1 r:core_node2 x:forwardingCollection_shard1_replica_n1] o.a.s.c.ShardLeaderElectionContext I am the new leader: https://127.0.0.1:40941/solr/forwardingCollection_shard1_replica_n1/ shard1 : [junit4] 2> 852808 INFO (zkCallback-1362-thread-2-processing-n:127.0.0.1:40941_solr) [n:127.0.0.1:40941_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> 852808 INFO (zkCallback-1362-thread-3-processing-n:127.0.0.1:40941_solr) [n:127.0.0.1:40941_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> 852857 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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> 852859 INFO (qtp9631235-7170) [n:127.0.0.1:40941_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=1519 : [junit4] 2> 852860 WARN (httpShardExecutor-3222-thread-1-processing-n:127.0.0.1:40941_solr [https:////127.0.0.1:40941//solr] https:////127.0.0.1:40941//solr) [n:127.0.0.1:40941_solr ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=$&p=$&t=test&e=1515996748843&s=ymWWTanFXlfJnkYUi/r+HaMKeVA="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:28 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:28 GMT : [junit4] 2> 852868 INFO (qtp9631235-7172) [n:127.0.0.1:40941_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> 852959 INFO (zkCallback-1362-thread-3-processing-n:127.0.0.1:40941_solr) [n:127.0.0.1:40941_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> 852959 INFO (zkCallback-1362-thread-2-processing-n:127.0.0.1:40941_solr) [n:127.0.0.1:40941_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> 853102 INFO (OverseerCollectionConfigSetProcessor-99350002448400390-127.0.0.1:40941_solr-n_0000000000) [n:127.0.0.1:40941_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> 853868 INFO (qtp9631235-7172) [n:127.0.0.1:40941_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=2774 : [junit4] 2> 853869 WARN (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[607345A73B2456EA]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=user&p=user&t=test&e=1515996748597&s=SXUJgIGdLeEuFacohlPCTzBHrDY="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:28 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:28 GMT : [junit4] 2> 853869 INFO (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[607345A73B2456EA]) [ ] o.a.s.c.AbstractDistribZkTestBase Wait for recoveries to finish - collection: forwardingCollection failOnTimeout:true timeout (sec):100 : [junit4] 2> 853869 INFO (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[607345A73B2456EA]) [ ] o.a.s.c.AbstractDistribZkTestBase Recoveries finished - collection: forwardingCollection : [junit4] 2> 853873 INFO (qtp9631235-7172) [n:127.0.0.1:40941_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> 853874 WARN (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[607345A73B2456EA]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=user&p=user&t=test&e=1515996751377&s=jWsUk51BbMwaRU7HiGenB8gaeGs="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:31 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:31 GMT : [junit4] 2> 853919 INFO (qtp2018146-7159) [n:127.0.0.1:44219_solr ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores : [junit4] 2> 853922 INFO (qtp9631235-7162) [n:127.0.0.1:40941_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> 853923 WARN (qtp2018146-7159) [n:127.0.0.1:44219_solr ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=$&p=$&t=test&e=1515996751425&s=pt3l9WPnA6CsqnggJLac4bZjslQ="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:31 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:31 GMT : [junit4] 2> 853927 WARN (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[607345A73B2456EA]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=user&p=user&t=test&e=1515996751422&s=UXT5V59Toi0WyvJt6tQR2lShGH0="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:31 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:31 GMT : [junit4] 2> 853927 WARN (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[607345A73B2456EA]) [ ] o.a.h.c.p.ResponseProcessCookies Invalid cookie header: "Set-Cookie: hadoop.auth="u=$&p=$&t=test&e=1515996751425&s=pt3l9WPnA6CsqnggJLac4bZjslQ="; Path=/; Domain=127.0.0.1; Expires= , 15- -2018 06:12:31 GMT; Secure; HttpOnly". Invalid 'expires' attribute: , 15- -2018 06:12:31 GMT : [junit4] 2> 853927 INFO (TEST-TestSolrCloudWithSecureImpersonation.testForwarding-seed#[607345A73B2456EA]) [ ] o.a.s.SolrTestCaseJ4 ###Ending testForwarding : [junit4] 2> 853928 INFO (jetty-closer-1346-thread-2) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@1c41bd6{SSL,[ssl, http/1.1]}{127.0.0.1:0} : [junit4] 2> 853928 INFO (jetty-closer-1346-thread-2) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=15275865 : [junit4] 2> 853929 INFO (jetty-closer-1346-thread-1) [ ] o.e.j.s.AbstractConnector Stopped ServerConnector@1410f10{SSL,[ssl, http/1.1]}{127.0.0.1:0} : [junit4] 2> 853929 INFO (jetty-closer-1346-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null : [junit4] 2> 853929 INFO (jetty-closer-1346-thread-1) [ ] o.a.s.c.CoreContainer Shutting down CoreContainer instance=8601253 : [junit4] 2> 853929 INFO (jetty-closer-1346-thread-2) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@c82e2c: rootName = solr_44219, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@96e270 : [junit4] 2> 853929 INFO (jetty-closer-1346-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.node, tag=null : [junit4] 2> 853929 INFO (jetty-closer-1346-thread-1) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@15fb89c: rootName = solr_40941, domain = solr.node, service url = null, agent id = null] for registry solr.node / com.codahale.metrics.MetricRegistry@1f144e6 : [junit4] 2> 853933 INFO (jetty-closer-1346-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null : [junit4] 2> 853933 INFO (jetty-closer-1346-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jvm, tag=null : [junit4] 2> 853933 INFO (jetty-closer-1346-thread-2) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@190427d: rootName = solr_44219, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@32710e : [junit4] 2> 853933 INFO (jetty-closer-1346-thread-1) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@1b2dff5: rootName = solr_40941, domain = solr.jvm, service url = null, agent id = null] for registry solr.jvm / com.codahale.metrics.MetricRegistry@32710e : [junit4] 2> 853936 INFO (jetty-closer-1346-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null : [junit4] 2> 853936 INFO (jetty-closer-1346-thread-2) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@7f5d3b: rootName = solr_44219, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@dff10 : [junit4] 2> 853937 INFO (jetty-closer-1346-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null : [junit4] 2> 853937 INFO (jetty-closer-1346-thread-1) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@1c4bd73: rootName = solr_40941, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@dff10 : [junit4] 2> 853937 INFO (jetty-closer-1346-thread-2) [ ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:44219_solr : [junit4] 2> 853937 INFO (jetty-closer-1346-thread-2) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null : [junit4] 2> 853938 INFO (jetty-closer-1346-thread-1) [ ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:40941_solr : [junit4] 2> 853938 INFO (zkCallback-1361-thread-2-processing-n:127.0.0.1:44219_solr) [n:127.0.0.1:44219_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1) : [junit4] 2> 853938 INFO (zkCallback-1362-thread-2-processing-n:127.0.0.1:40941_solr) [n:127.0.0.1:40941_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1) : [junit4] 2> 853938 ERROR (Thread[Thread-1977,5,TGRP-TestSolrCloudWithSecureImpersonation]) [n:127.0.0.1:44219_solr ] o.a.h.s.t.d.AbstractDelegationTokenSecretManager ExpiredTokenRemover received java.lang.InterruptedException: sleep interrupted : [junit4] 2> 853939 INFO (jetty-closer-1346-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null : [junit4] 2> 853939 INFO (zkCallback-1362-thread-3-processing-n:127.0.0.1:40941_solr) [n:127.0.0.1:40941_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (0) : [junit4] 2> 853939 INFO (coreCloseExecutor-3239-thread-1) [n:127.0.0.1:40941_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@1e5f6f3 : [junit4] 2> 853939 INFO (coreCloseExecutor-3239-thread-1) [n:127.0.0.1:40941_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=31848179 : [junit4] 2> 853939 INFO (coreCloseExecutor-3239-thread-1) [n:127.0.0.1:40941_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@13896c: rootName = solr_40941, 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@12ebbf3 : [junit4] 2> 853952 INFO (jetty-closer-1346-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@19b199e{/solr,null,UNAVAILABLE} : [junit4] 2> 853957 INFO (coreCloseExecutor-3239-thread-1) [n:127.0.0.1:40941_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=31848179 : [junit4] 2> 853958 INFO (jetty-closer-1346-thread-1) [ ] o.a.s.c.Overseer Overseer (id=99350002448400390-127.0.0.1:40941_solr-n_0000000000) closing : [junit4] 2> 853959 INFO (OverseerStateUpdate-99350002448400390-127.0.0.1:40941_solr-n_0000000000) [n:127.0.0.1:40941_solr ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:40941_solr : [junit4] 2> 853959 WARN (OverseerAutoScalingTriggerThread-99350002448400390-127.0.0.1:40941_solr-n_0000000000) [n:127.0.0.1:40941_solr ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting. : [junit4] 2> 853960 ERROR (Thread[Thread-1978,5,TGRP-TestSolrCloudWithSecureImpersonation]) [n:127.0.0.1:40941_solr ] o.a.h.s.t.d.AbstractDelegationTokenSecretManager ExpiredTokenRemover received java.lang.InterruptedException: sleep interrupted : [junit4] 2> 853960 INFO (jetty-closer-1346-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@7870{/solr,null,UNAVAILABLE} : [junit4] 2> 853961 ERROR (SUITE-TestSolrCloudWithSecureImpersonation-seed#[607345A73B2456EA]-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> 853961 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[607345A73B2456EA]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:45301 45301 : [junit4] 2> 854183 INFO (Thread-1960) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:45301 45301 : [junit4] 2> 854184 WARN (Thread-1960) [ ] 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> 2 /solr/security.json : [junit4] 2> : [junit4] 2> Maximum concurrent data watches above limit: : [junit4] 2> : [junit4] 2> 5 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMKeyIdRoot : [junit4] 2> 5 /solr/collections/forwardingCollection/state.json : [junit4] 2> 3 /solr/clusterstate.json : [junit4] 2> 3 /solr/clusterprops.json : [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> 2 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMSeqNumRoot : [junit4] 2> : [junit4] 2> Maximum concurrent children watches above limit: : [junit4] 2> : [junit4] 2> 4 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMTokensRoot : [junit4] 2> 3 /solr/live_nodes : [junit4] 2> 3 /solr/collections : [junit4] 2> 3 /solr/security/zkdtsm/ZKDTSMRoot/ZKDTSMMasterKeyRoot : [junit4] 2> : [junit4] 2> 854194 INFO (SUITE-TestSolrCloudWithSecureImpersonation-seed#[607345A73B2456EA]-worker) [ ] o.a.s.SolrTestCaseJ4 ------------------------------------------------------- Done waiting for tracked resources to be released : [junit4] 2> Jan 14, 2018 8:12:31 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks : [junit4] 2> WARNING: Will linger awaiting termination of 3 leaked thread(s). : [junit4] 2> Jan 14, 2018 8:12:51 PM com.carrotsearch.randomizedtesting.ThreadLeakControl checkThreadLeaks : [junit4] 2> SEVERE: 2 threads leaked from SUITE scope at org.apache.solr.cloud.TestSolrCloudWithSecureImpersonation: : [junit4] 2> 1) Thread[id=7210, name=jetty-launcher-1345-thread-2-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> 2) Thread[id=7212, name=jetty-launcher-1345-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 14, 2018 8:12:51 PM com.carrotsearch.randomizedtesting.ThreadLeakControl tryToInterruptAll : [junit4] 2> INFO: Starting to interrupt leaked threads: : [junit4] 2> 1) Thread[id=7210, name=jetty-launcher-1345-thread-2-EventThread, state=TIMED_WAITING, group=TGRP-TestSolrCloudWithSecureImpersonation] : [junit4] 2> 2) Thread[id=7212, name=jetty-launcher-1345-thread-1-EventThread, state=TIMED_WAITING, group=TGRP-TestSolrCloudWithSecureImpersonation] : [junit4] 2> 874293 ERROR (jetty-launcher-1345-thread-2-EventThread) [n:127.0.0.1:40941_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.apa : : [...truncated too long message...] : : xecutor-3556-thread-1) [n:127.0.0.1:42819_solr c:.system s:shard1 r:core_node5 x:.system_shard1_replica_n2] o.a.s.c.SolrCore [.system_shard1_replica_n2] CLOSING SolrCore org.apache.solr.core.SolrCore@3d8667 : [junit4] 2> 1160127 INFO (coreCloseExecutor-3556-thread-1) [n:127.0.0.1:42819_solr c:.system s:shard1 r:core_node5 x:.system_shard1_replica_n2] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core..system.shard1.replica_n2, tag=4032103 : [junit4] 2> 1160128 INFO (coreCloseExecutor-3556-thread-1) [n:127.0.0.1:42819_solr c:.system s:shard1 r:core_node5 x:.system_shard1_replica_n2] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@c08e7f: rootName = solr_42819, domain = solr.core..system.shard1.replica_n2, service url = null, agent id = null] for registry solr.core..system.shard1.replica_n2 / com.codahale.metrics.MetricRegistry@1b3127c : [junit4] 2> 1160131 INFO (jetty-closer-1551-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null : [junit4] 2> 1160131 INFO (jetty-closer-1551-thread-1) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@1138f7d: rootName = solr_40241, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@7404be : [junit4] 2> 1160131 INFO (jetty-closer-1551-thread-3) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.jetty, tag=null : [junit4] 2> 1160132 INFO (jetty-closer-1551-thread-1) [ ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:40241_solr : [junit4] 2> 1160132 INFO (jetty-closer-1551-thread-3) [ ] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@101fa3: rootName = solr_45485, domain = solr.jetty, service url = null, agent id = null] for registry solr.jetty / com.codahale.metrics.MetricRegistry@7404be : [junit4] 2> 1160132 INFO (zkCallback-1576-thread-3-processing-n:127.0.0.1:42819_solr) [n:127.0.0.1:42819_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1) : [junit4] 2> 1160132 INFO (zkCallback-1572-thread-2-processing-n:127.0.0.1:40241_solr) [n:127.0.0.1:40241_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1) : [junit4] 2> 1160133 INFO (zkCallback-1596-thread-1-processing-n:127.0.0.1:45485_solr) [n:127.0.0.1:45485_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (2) -> (1) : [junit4] 2> 1160133 INFO (jetty-closer-1551-thread-1) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null : [junit4] 2> 1160134 INFO (jetty-closer-1551-thread-3) [ ] o.a.s.c.ZkController Remove node as live in ZooKeeper:/live_nodes/127.0.0.1:45485_solr : [junit4] 2> 1160135 INFO (jetty-closer-1551-thread-3) [ ] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.cluster, tag=null : [junit4] 2> 1160135 INFO (zkCallback-1576-thread-3-processing-n:127.0.0.1:42819_solr) [n:127.0.0.1:42819_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (0) : [junit4] 2> 1160135 INFO (zkCallback-1572-thread-2-processing-n:127.0.0.1:40241_solr) [n:127.0.0.1:40241_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (0) : [junit4] 2> 1160135 INFO (jetty-closer-1551-thread-3) [ ] o.a.s.c.TransientSolrCoreCacheDefault Allocating transient cache for 2147483647 transient cores : [junit4] 2> 1160135 INFO (zkCallback-1596-thread-1-processing-n:127.0.0.1:45485_solr) [n:127.0.0.1:45485_solr ] o.a.s.c.c.ZkStateReader Updated live nodes from ZooKeeper... (1) -> (0) : [junit4] 2> 1160136 INFO (coreCloseExecutor-3557-thread-1) [n:127.0.0.1:40241_solr c:.system s:shard1 r:core_node3 x:.system_shard1_replica_n1] o.a.s.c.SolrCore [.system_shard1_replica_n1] CLOSING SolrCore org.apache.solr.core.SolrCore@92f7f6 : [junit4] 2> 1160137 INFO (coreCloseExecutor-3557-thread-1) [n:127.0.0.1:40241_solr c:.system s:shard1 r:core_node3 x:.system_shard1_replica_n1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core..system.shard1.replica_n1, tag=9631734 : [junit4] 2> 1160137 INFO (coreCloseExecutor-3557-thread-1) [n:127.0.0.1:40241_solr c:.system s:shard1 r:core_node3 x:.system_shard1_replica_n1] o.a.s.m.r.SolrJmxReporter Closing reporter [org.apache.solr.metrics.reporters.SolrJmxReporter@104e79f: rootName = solr_40241, domain = solr.core..system.shard1.replica_n1, service url = null, agent id = null] for registry solr.core..system.shard1.replica_n1 / com.codahale.metrics.MetricRegistry@a9da5f : [junit4] 2> 1160137 INFO (jetty-closer-1551-thread-3) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@cd808{/solr,null,UNAVAILABLE} : [junit4] 2> 1160141 INFO (coreCloseExecutor-3556-thread-1) [n:127.0.0.1:42819_solr c:.system s:shard1 r:core_node5 x:.system_shard1_replica_n2] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection..system.shard1.leader, tag=4032103 : [junit4] 2> 1160145 INFO (jetty-closer-1551-thread-2) [ ] o.a.s.c.Overseer Overseer (id=99350023575765001-127.0.0.1:42819_solr-n_0000000000) closing : [junit4] 2> 1160145 INFO (OverseerStateUpdate-99350023575765001-127.0.0.1:42819_solr-n_0000000000) [n:127.0.0.1:42819_solr ] o.a.s.c.Overseer Overseer Loop exiting : 127.0.0.1:42819_solr : [junit4] 2> 1160145 INFO (coreCloseExecutor-3557-thread-1) [n:127.0.0.1:40241_solr c:.system s:shard1 r:core_node3 x:.system_shard1_replica_n1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection..system.shard1.leader, tag=9631734 : [junit4] 2> 1160145 WARN (OverseerAutoScalingTriggerThread-99350023575765001-127.0.0.1:42819_solr-n_0000000000) [n:127.0.0.1:42819_solr ] o.a.s.c.a.OverseerTriggerThread OverseerTriggerThread woken up but we are closed, exiting. : [junit4] 2> 1160147 INFO (jetty-closer-1551-thread-2) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@1a7059b{/solr,null,UNAVAILABLE} : [junit4] 2> 1161647 INFO (jetty-closer-1551-thread-1) [ ] o.e.j.s.h.ContextHandler Stopped o.e.j.s.ServletContextHandler@1b8b24a{/solr,null,UNAVAILABLE} : [junit4] 2> 1161648 ERROR (SUITE-TestClusterStateProvider-seed#[607345A73B2456EA]-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> 1161648 INFO (SUITE-TestClusterStateProvider-seed#[607345A73B2456EA]-worker) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:35357 35357 : [junit4] 2> 1176670 INFO (Thread-1472) [ ] o.a.s.c.ZkTestServer connecting to 127.0.0.1:35357 35357 : [junit4] 2> 1176671 WARN (Thread-1472) [ ] o.a.s.c.ZkTestServer Watch limit violations: : [junit4] 2> Maximum concurrent create/delete watches above limit: : [junit4] 2> : [junit4] 2> 5 /solr/aliases.json : [junit4] 2> 4 /solr/security.json : [junit4] 2> 3 /solr/configs/.system : [junit4] 2> 3 /solr/configs/.system/managed-schema : [junit4] 2> : [junit4] 2> Maximum concurrent data watches above limit: : [junit4] 2> : [junit4] 2> 20 /solr/collections/.system/state.json : [junit4] 2> 5 /solr/clusterstate.json : [junit4] 2> 5 /solr/clusterprops.json : [junit4] 2> 2 /solr/overseer_elect/election/99350023575764999-127.0.0.1:40241_solr-n_0000000001 : [junit4] 2> : [junit4] 2> Maximum concurrent children watches above limit: : [junit4] 2> : [junit4] 2> 5 /solr/live_nodes : [junit4] 2> 5 /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/J2/temp/solr.cloud.autoscaling.sim.TestClusterStateProvider_607345A73B2456EA-001 : [junit4] 2> NOTE: test params are: codec=Asserting(Lucene70): {}, docValues:{}, maxPointsInLeafNode=1858, maxMBSortInHeap=5.144544667996209, sim=Asserting(org.apache.lucene.search.similarities.AssertingSimilarity@cd89e5), locale=da, timezone=Pacific/Truk : [junit4] 2> NOTE: Linux 4.13.0-26-generic i386/Oracle Corporation 1.8.0_144 (32-bit)/cpus=8,threads=1,free=237171552,total=518979584 : [junit4] 2> NOTE: All tests run in this JVM: [TestTolerantUpdateProcessorCloud, TestSolrFieldCacheBean, TestFieldCacheSortRandom, DistribJoinFromCollectionTest, ExitableDirectoryReaderTest, UniqFieldsUpdateProcessorFactoryTest, TestSolrConfigHandler, FullSolrCloudDistribCmdsTest, TestExtendedDismaxParser, CdcrReplicationHandlerTest, DistributedFacetSimpleRefinementLongTailTest, TestExclusionRuleCollectionAccess, TestFieldSortValues, TestFunctionQuery, TestCoreDiscovery, MultiThreadedOCPTest, TestDistributedGrouping, TestSolrDeletionPolicy2, DistributedExpandComponentTest, ReplaceNodeTest, TestJsonRequest, TestRestoreCore, TestSolrCloudWithKerberosAlt, TestAuthenticationFramework, AliasIntegrationTest, TestReplicaProperties, TestPerFieldSimilarityWithDefaultOverride, LargeFieldTest, CdcrUpdateLogTest, TestNestedDocsSort, FieldMutatingUpdateProcessorTest, TestTrieFacet, TestCollectionAPI, ShardSplitTest, DocValuesNotIndexedTest, PreAnalyzedUpdateProcessorTest, NodeAddedTriggerTe st, TestManagedSchemaThreadSafety, MetricsConfigTest, UnloadDistributedZkTest, TestImpersonationWithHadoopAuth, TestPartialUpdateDeduplication, TestManagedSynonymFilterFactory, SolrCoreCheckLockOnStartupTest, TestMacros, TestCloudJSONFacetJoinDomain, TestBackupRepositoryFactory, BooleanFieldTest, TestDeleteCollectionOnDownNodes, TestLFUCache, CSVRequestHandlerTest, HighlighterTest, IndexBasedSpellCheckerTest, TestReload, TestStressInPlaceUpdates, TestClusterStateProvider] : [junit4] Completed [274/767 (2!)] on J2 in 21.09s, 2 tests, 1 failure <<< FAILURES! : : [...truncated 45454 lines...] : -Hoss http://www.lucidworks.com/
--------------------------------------------------------------------- To unsubscribe, e-mail: [email protected] For additional commands, e-mail: [email protected]
