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 2014/11/02 13:10:27 UTC
[JENKINS] Lucene-Solr-5.x-MacOSX (64bit/jdk1.8.0) - Build # 1875 -
Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-5.x-MacOSX/1875/
Java: 64bit/jdk1.8.0 -XX:+UseCompressedOops -XX:+UseSerialGC (asserts: true)
1 tests failed.
FAILED: org.apache.solr.cloud.DistribDocExpirationUpdateProcessorTest.testDistribSearch
Error Message:
Give up waiting for no results: q=id%3A999&rows=0&_trace=did_it_expire_yet&_stateVer_=collection1%3A15 expected:<0> but was:<1>
Stack Trace:
java.lang.AssertionError: Give up waiting for no results: q=id%3A999&rows=0&_trace=did_it_expire_yet&_stateVer_=collection1%3A15 expected:<0> but was:<1>
at __randomizedtesting.SeedInfo.seed([E83088324E2CED55:69D6062A39738D69]: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:472)
at org.apache.solr.cloud.DistribDocExpirationUpdateProcessorTest.waitForNoResults(DistribDocExpirationUpdateProcessorTest.java:189)
at org.apache.solr.cloud.DistribDocExpirationUpdateProcessorTest.doTest(DistribDocExpirationUpdateProcessorTest.java:95)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:869)
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:483)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1618)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:827)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:863)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:877)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:365)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:798)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:458)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:836)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:738)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:772)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:783)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
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:54)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:65)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:365)
at java.lang.Thread.run(Thread.java:745)
Build Log:
[...truncated 10687 lines...]
[junit4] Suite: org.apache.solr.cloud.DistribDocExpirationUpdateProcessorTest
[junit4] 2> Creating dataDir: /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/init-core-data-001
[junit4] 2> 373020 T679 oas.SolrTestCaseJ4.buildSSLConfig Randomized ssl (true) and clientAuth (false)
[junit4] 2> 373020 T679 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4] 2> 373039 T679 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4] 2> 373041 T679 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4] 2> 373044 T680 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4] 2> 373145 T679 oasc.ZkTestServer.run start zk server on port:55435
[junit4] 2> 373146 T679 oascc.SolrZkClient.createZkCredentialsToAddAutomatically Using default ZkCredentialsProvider
[junit4] 2> 373149 T679 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 373157 T686 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6572edf2 name:ZooKeeperConnection Watcher:127.0.0.1:55435 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 373158 T679 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 373158 T679 oascc.SolrZkClient.createZkACLProvider Using default ZkACLProvider
[junit4] 2> 373158 T679 oascc.SolrZkClient.makePath makePath: /solr
[junit4] 2> 373164 T679 oascc.SolrZkClient.createZkCredentialsToAddAutomatically Using default ZkCredentialsProvider
[junit4] 2> 373167 T679 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 373171 T688 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5325e6aa name:ZooKeeperConnection Watcher:127.0.0.1:55435/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 373172 T679 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 373172 T679 oascc.SolrZkClient.createZkACLProvider Using default ZkACLProvider
[junit4] 2> 373172 T679 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4] 2> 373181 T679 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4] 2> 373188 T679 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4] 2> 373194 T679 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4] 2> 373200 T679 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/core/src/test-files/solr/collection1/conf/solrconfig-doc-expire-update-processor.xml to /configs/conf1/solrconfig.xml
[junit4] 2> 373201 T679 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4] 2> 373208 T679 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/core/src/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4] 2> 373208 T679 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4] 2> 373212 T679 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/core/src/test-files/solr/collection1/conf/solrconfig.snippet.randomindexconfig.xml to /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 373212 T679 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.snippet.randomindexconfig.xml
[junit4] 2> 373221 T679 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/core/src/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4] 2> 373222 T679 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4] 2> 373227 T679 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/core/src/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4] 2> 373228 T679 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4] 2> 373234 T679 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/core/src/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4] 2> 373235 T679 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4] 2> 373242 T679 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/core/src/test-files/solr/collection1/conf/enumsConfig.xml to /configs/conf1/enumsConfig.xml
[junit4] 2> 373244 T679 oascc.SolrZkClient.makePath makePath: /configs/conf1/enumsConfig.xml
[junit4] 2> 373253 T679 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/core/src/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4] 2> 373254 T679 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4] 2> 373262 T679 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/core/src/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 373264 T679 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4] 2> 373270 T679 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/core/src/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4] 2> 373271 T679 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4] 2> 373276 T679 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/core/src/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4] 2> 373276 T679 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4] 2> 373296 T679 oascc.SolrZkClient.createZkCredentialsToAddAutomatically Using default ZkCredentialsProvider
[junit4] 2> 373297 T679 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 373305 T690 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@85b9038 name:ZooKeeperConnection Watcher:127.0.0.1:55435/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 373306 T679 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 373306 T679 oascc.SolrZkClient.createZkACLProvider Using default ZkACLProvider
[junit4] 2> 375286 T679 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 375311 T679 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2] of [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
[junit4] 2> 375327 T679 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:55439
[junit4] 2> 375342 T679 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 375343 T679 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 375344 T679 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-002
[junit4] 2> 375344 T679 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-002/'
[junit4] 2> 375389 T679 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-002/solr.xml
[junit4] 2> 375405 T679 oasc.CoreContainer.<init> New CoreContainer 1448741917
[junit4] 2> 375406 T679 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-002/]
[junit4] 2> 375406 T679 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
[junit4] 2> 375406 T679 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to:
[junit4] 2> 375406 T679 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 375407 T679 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 375407 T679 oashc.HttpShardHandlerFactory.getParameter Setting maxConnections to: 10000
[junit4] 2> 375407 T679 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 375408 T679 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 375408 T679 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 375408 T679 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 375409 T679 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 375411 T679 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=false
[junit4] 2> 375414 T679 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 375414 T679 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 375414 T679 oasc.CoreContainer.load Host Name: 127.0.0.1
[junit4] 2> 375414 T679 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55435/solr
[junit4] 2> 375414 T679 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 375415 T679 oascc.SolrZkClient.createZkCredentialsToAddAutomatically Using default ZkCredentialsProvider
[junit4] 2> 375417 T679 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 375430 T701 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13da4bbc name:ZooKeeperConnection Watcher:127.0.0.1:55435 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 375431 T679 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 375431 T679 oascc.SolrZkClient.createZkACLProvider Using default ZkACLProvider
[junit4] 2> 375437 T679 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 375445 T703 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@63f12932 name:ZooKeeperConnection Watcher:127.0.0.1:55435/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 375446 T679 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 375449 T679 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4] 2> 375459 T679 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4] 2> 375486 T679 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-running
[junit4] 2> 375511 T679 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-completed
[junit4] 2> 375521 T679 oascc.SolrZkClient.makePath makePath: /overseer/collection-map-failure
[junit4] 2> 375530 T679 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4] 2> 375535 T679 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55439_
[junit4] 2> 375537 T679 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55439_
[junit4] 2> 375544 T679 oascc.SolrZkClient.makePath makePath: /overseer_elect
[junit4] 2> 375550 T679 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4] 2> 375554 T679 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 375559 T679 oasc.OverseerElectionContext.runLeaderProcess I am going to be the leader 127.0.0.1:55439_
[junit4] 2> 375559 T679 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4] 2> 375565 T679 oasc.Overseer.start Overseer (id=92728421209866244-127.0.0.1:55439_-n_0000000000) starting
[junit4] 2> 375577 T679 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4] 2> 375604 T679 oasc.OverseerAutoReplicaFailoverThread.<init> Starting OverseerAutoReplicaFailoverThread autoReplicaFailoverWorkLoopDelay=10000 autoReplicaFailoverWaitAfterExpiration=30000 autoReplicaFailoverBadNodeExpiration=60000
[junit4] 2> 375606 T705 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4] 2> 375612 T679 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4] 2> 375621 T679 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4] 2> 375628 T679 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 375647 T704 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4] 2> 375655 T707 oasc.ZkController.publish publishing core=collection1 state=down collection=control_collection
[junit4] 2> 375655 T707 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 375657 T707 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 375658 T708 oasc.DistributedQueue$LatchWatcher.process NodeChildrenChanged fired on path /overseer/queue state SyncConnected
[junit4] 2> 375668 T704 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "base_url":"https://127.0.0.1:55439",
[junit4] 2> "node_name":"127.0.0.1:55439_",
[junit4] 2> "numShards":"1",
[junit4] 2> "state":"down",
[junit4] 2> "shard":null,
[junit4] 2> "collection":"control_collection",
[junit4] 2> "operation":"state"}
[junit4] 2> 375668 T704 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with shards [shard1]
[junit4] 2> 375668 T704 oasc.Overseer$ClusterStateUpdater.createCollection state version control_collection 1
[junit4] 2> 375669 T704 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 375678 T708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 376660 T707 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 376660 T707 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4] 2> 376661 T707 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 376662 T707 oascc.ZkStateReader.readConfigName Load collection config from:/collections/control_collection
[junit4] 2> 376664 T707 oascc.ZkStateReader.readConfigName path=/collections/control_collection configName=conf1 specified config exists in ZooKeeper
[junit4] 2> 376664 T707 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-002/collection1/'
[junit4] 2> 376671 T707 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-002/collection1/lib/.svn/' to classloader
[junit4] 2> 376673 T707 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-002/collection1/lib/classes/' to classloader
[junit4] 2> 376675 T707 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-002/collection1/lib/README' to classloader
[junit4] 2> 376745 T707 oasc.SolrConfig.<init> Using Lucene MatchVersion: 5.0.0
[junit4] 2> 376763 T707 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 376766 T707 oass.IndexSchema.readSchema Reading Solr Schema from /configs/conf1/schema.xml
[junit4] 2> 376774 T707 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 376957 T707 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 376957 T707 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 376960 T707 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 376968 T707 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 377114 T707 oasc.CoreContainer.create Creating SolrCore 'collection1' using configuration from collection control_collection
[junit4] 2> 377115 T707 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 377116 T707 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-002/collection1/, dataDir=/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/control/data/
[junit4] 2> 377116 T707 oasc.SolrCore.<init> JMX monitoring not detected for core: collection1
[junit4] 2> 377117 T707 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/control/data
[junit4] 2> 377118 T707 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/control/data/index/
[junit4] 2> 377118 T707 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/control/data/index' doesn't exist. Creating new index...
[junit4] 2> 377119 T707 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/control/data/index
[junit4] 2> 377119 T707 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=12, maxMergeAtOnceExplicit=14, maxMergedSegmentMB=36.8740234375, floorSegmentMB=0.587890625, forceMergeDeletesPctAllowed=20.112168822910203, segmentsPerTier=39.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 377121 T707 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory(id=lucene-5fb24c88)),segFN=segments_1,generation=1}
[junit4] 2> 377121 T707 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 377124 T707 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "convert-ttl-defaults"
[junit4] 2> 377124 T707 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "convert-ttl-field"
[junit4] 2> 377125 T707 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "convert-ttl-param"
[junit4] 2> 377125 T707 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "convert-ttl-field-with-param-default"
[junit4] 2> 377126 T707 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "scheduled-delete" (default)
[junit4] 2> 377127 T707 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "scheduled-delete" (default)
[junit4] 2> 377129 T707 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 377129 T707 oasc.RequestHandlers.initHandlersFromConfig created /update/json: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 377130 T707 oasc.RequestHandlers.initHandlersFromConfig created /update/json/docs: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 377130 T707 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 377130 T707 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 377130 T707 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 377131 T707 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
[junit4] 2> 377131 T707 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 377131 T707 oasc.RequestHandlers.initHandlersFromConfig created /admin/: solr.admin.AdminHandlers
[junit4] 2> 377142 T707 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 377145 T707 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 377150 T707 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 377152 T707 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 377157 T707 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 377157 T707 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 377159 T707 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=25, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 377160 T707 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory(id=lucene-5fb24c88)),segFN=segments_1,generation=1}
[junit4] 2> 377160 T707 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 377160 T707 oass.SolrIndexSearcher.<init> Opening Searcher@7032fec5[collection1] main
[junit4] 2> 377161 T707 oascc.ZkStateReader.readConfigName Load collection config from:/collections/control_collection
[junit4] 2> 377166 T707 oascc.ZkStateReader.readConfigName path=/collections/control_collection configName=conf1 specified config exists in ZooKeeper
[junit4] 2> 377166 T707 oasr.ManagedResourceStorage.newStorageIO Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1
[junit4] 2> 377170 T707 oasr.ManagedResourceStorage$ZooKeeperStorageIO.configure Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 377171 T707 oasr.RestManager.init Initializing RestManager with initArgs: {}
[junit4] 2> 377171 T707 oasr.ManagedResourceStorage.load Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 377174 T707 oasr.ManagedResourceStorage$ZooKeeperStorageIO.openInputStream No data found for znode /configs/conf1/_rest_managed.json
[junit4] 2> 377175 T707 oasr.ManagedResourceStorage.load Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 377178 T707 oascc.SolrZkClient.makePath makePath: /configs/conf1/_rest_managed.json
[junit4] 2> 377187 T707 oasr.ManagedResourceStorage$ZooKeeperStorageIO$1.close Wrote 38 bytes to new znode /configs/conf1/_rest_managed.json
[junit4] 2> 377187 T707 oasr.ManagedResourceStorage$JsonStorage.store Saved JSON object to path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 377188 T707 oasr.RestManager.init Initializing 0 registered ManagedResources
[junit4] 2> 377192 T709 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7032fec5[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 377192 T707 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 377195 T713 oasc.ZkController.register Register replica - core:collection1 address:https://127.0.0.1:55439 collection:control_collection shard:shard1
[junit4] 2> 377199 T679 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0
[junit4] 2> 377200 T679 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 377205 T713 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4] 2> 377209 T679 oascc.SolrZkClient.createZkCredentialsToAddAutomatically Using default ZkCredentialsProvider
[junit4] 2> 377212 T679 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 377219 T715 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c6cf4a6 name:ZooKeeperConnection Watcher:127.0.0.1:55435/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 377219 T679 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 377220 T679 oascc.SolrZkClient.createZkACLProvider Using default ZkACLProvider
[junit4] 2> 377224 T679 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> 377226 T713 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4] 2> 377233 T708 oasc.DistributedQueue$LatchWatcher.process NodeChildrenChanged fired on path /overseer/queue state SyncConnected
[junit4] 2> 377234 T713 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 377235 T713 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> ASYNC NEW_CORE C367 name=collection1 org.apache.solr.core.SolrCore@11ec57e9 url=https://127.0.0.1:55439/collection1 node=127.0.0.1:55439_ C367_STATE=coll:control_collection core:collection1 props:{core=collection1, base_url=https://127.0.0.1:55439, node_name=127.0.0.1:55439_, state=down}
[junit4] 2> 377235 T713 C367 P55439 oasc.SyncStrategy.sync Sync replicas to https://127.0.0.1:55439/collection1/
[junit4] 2> 377236 T713 C367 P55439 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 377236 T713 C367 P55439 oasc.SyncStrategy.syncToMe https://127.0.0.1:55439/collection1/ has no replicas
[junit4] 2> 377236 T713 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: https://127.0.0.1:55439/collection1/ shard1
[junit4] 2> 377237 T713 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4] 2> 377236 T679 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:false cause connection loss:false
[junit4] 2> 377239 T679 oasc.AbstractFullDistribZkTestBase.createJettys Creating collection1 with stateFormat=2
[junit4] 2> 377240 T679 oascc.SolrZkClient.createZkCredentialsToAddAutomatically Using default ZkCredentialsProvider
[junit4] 2> 377241 T679 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 377246 T717 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6da1bf77 name:ZooKeeperConnection Watcher:127.0.0.1:55435/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 377247 T679 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 377247 T679 oascc.SolrZkClient.createZkACLProvider Using default ZkACLProvider
[junit4] 2> 377273 T708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 377273 T718 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 377307 T704 oasc.Overseer$ClusterStateUpdater.buildCollection building a new collection: collection1
[junit4] 2> 377307 T704 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with shards [shard1, shard2]
[junit4] 2> 377308 T704 oasc.Overseer$ClusterStateUpdater.createCollection state version collection1 2
[junit4] 2> 377316 T708 oasc.DistributedQueue$LatchWatcher.process NodeChildrenChanged fired on path /overseer/queue state SyncConnected
[junit4] 2> 377317 T704 oasc.Overseer$ClusterStateUpdater.updateZkStates going to create_collection /collections/collection1/state.json
[junit4] 2> 377322 T708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 377322 T718 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 377370 T708 oasc.DistributedQueue$LatchWatcher.process NodeChildrenChanged fired on path /overseer/queue state SyncConnected
[junit4] 2> 377376 T718 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 377376 T708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 377423 T713 oasc.ZkController.register We are https://127.0.0.1:55439/collection1/ and leader is https://127.0.0.1:55439/collection1/
[junit4] 2> 377424 T713 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=https://127.0.0.1:55439
[junit4] 2> 377424 T713 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 377425 T713 oasc.ZkController.publish publishing core=collection1 state=active collection=control_collection
[junit4] 2> 377426 T713 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 377431 T708 oasc.DistributedQueue$LatchWatcher.process NodeChildrenChanged fired on path /overseer/queue state SyncConnected
[junit4] 2> 377453 T704 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "core":"collection1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "roles":null,
[junit4] 2> "base_url":"https://127.0.0.1:55439",
[junit4] 2> "node_name":"127.0.0.1:55439_",
[junit4] 2> "numShards":"2",
[junit4] 2> "state":"active",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"control_collection",
[junit4] 2> "operation":"state"}
[junit4] 2> 377565 T718 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 377566 T708 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4] 2> 379301 T679 oasc.AbstractFullDistribZkTestBase.createJettys create jetty 1
[junit4] 2> 379302 T679 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 379310 T679 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2] of [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
[junit4] 2> 379312 T679 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:55444
[junit4] 2> 379315 T679 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 379315 T679 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 379316 T679 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-003
[junit4] 2> 379317 T679 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-003/'
[junit4] 2> 379377 T679 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-003/solr.xml
[junit4] 2> 379423 T679 oasc.CoreContainer.<init> New CoreContainer 1456866188
[junit4] 2> 379424 T679 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-003/]
[junit4] 2> 379424 T679 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
[junit4] 2> 379425 T679 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to:
[junit4] 2> 379425 T679 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 379425 T679 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 379426 T679 oashc.HttpShardHandlerFactory.getParameter Setting maxConnections to: 10000
[junit4] 2> 379426 T679 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 379426 T679 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 379427 T679 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 379427 T679 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 379427 T679 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 379431 T679 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=false
[junit4] 2> 379432 T679 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 379433 T679 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 379433 T679 oasc.CoreContainer.load Host Name: 127.0.0.1
[junit4] 2> 379433 T679 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55435/solr
[junit4] 2> 379434 T679 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 379435 T679 oascc.SolrZkClient.createZkCredentialsToAddAutomatically Using default ZkCredentialsProvider
[junit4] 2> 379436 T679 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 379439 T729 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7a0b15b6 name:ZooKeeperConnection Watcher:127.0.0.1:55435 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 379440 T679 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 379440 T679 oascc.SolrZkClient.createZkACLProvider Using default ZkACLProvider
[junit4] 2> 379449 T679 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 379452 T731 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@60679df5 name:ZooKeeperConnection Watcher:127.0.0.1:55435/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 379452 T679 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 379474 T679 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> ASYNC NEW_CORE C368 name=collection1 org.apache.solr.core.SolrCore@11ec57e9 url=https://127.0.0.1:55439/collection1 node=127.0.0.1:55439_ C368_STATE=coll:control_collection core:collection1 props:{core=collection1, base_url=https://127.0.0.1:55439, node_name=127.0.0.1:55439_, state=active, leader=true}
[junit4] 2> 380191 T710 C368 P55439 oasup.DocExpirationUpdateProcessorFactory$DeleteExpiredDocsRunnable.run Begining periodic deletion of expired docs
[junit4] 2> 380196 T710 C368 P55439 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
[junit4] 2> 380196 T710 C368 P55439 oasc.SolrCore.openNewSearcher SolrIndexSearcher has not changed - not re-opening: org.apache.solr.search.SolrIndexSearcher
[junit4] 2> 380197 T710 C368 P55439 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 380197 T710 C368 P55439 oasup.LogUpdateProcessor.finish [collection1] {deleteByQuery={!cache=false}eXpField_tdt:[* TO 2014-11-02T10:17:06.483Z] (-1483654746848886784),commit=} 0 6
[junit4] 2> 380198 T710 C368 P55439 oasup.DocExpirationUpdateProcessorFactory$DeleteExpiredDocsRunnable.run Finished periodic deletion of expired docs
[junit4] 2> 380496 T679 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55444_
[junit4] 2> 380498 T679 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55444_
[junit4] 2> 380509 T679 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 380527 T733 oasc.ZkController.publish publishing core=collection1 state=down collection=collection1
[junit4] 2> 380527 T733 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 380532 T708 oasc.DistributedQueue$LatchWatcher.process NodeChildrenChanged fired on path /overseer/queue state SyncConnected
[junit4] 2> 380535 T733 oasc.ZkController.preRegister Registering watch for external collection collection1
[junit4] 2> 380535 T733 oascc.ZkStateReader.addZkWatch addZkWatch collection1
[junit4] 2> 380536 T733 oascc.ZkStateReader.addZkWatch Updating collection state at /collections/collection1/state.json from ZooKeeper...
[junit4] 2> 380542 T733 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 0
[junit4] 2> 380542 T733 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 380557 T704 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "base_url":"https://127.0.0.1:55444",
[junit4] 2> "node_name":"127.0.0.1:55444_",
[junit4] 2> "numShards":"2",
[junit4] 2> "state":"down",
[junit4] 2> "shard":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "operation":"state"}
[junit4] 2> 380568 T704 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4] 2> 380570 T704 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard2
[junit4] 2> 380588 T708 oasc.DistributedQueue$LatchWatcher.process NodeChildrenChanged fired on path /overseer/queue state SyncConnected
[junit4] 2> 380589 T704 oasc.Overseer$ClusterStateUpdater.updateZkStates going to update_collection /collections/collection1/state.json
[junit4] 2> 380590 T732 oascc.ZkStateReader$7.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json, has occurred - updating...
[junit4] 2> 380592 T732 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 1
[junit4] 2> 381545 T733 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 381546 T733 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4] 2> 381549 T733 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 381549 T733 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 381554 T733 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper
[junit4] 2> 381555 T733 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-003/collection1/'
[junit4] 2> 381558 T733 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-003/collection1/lib/.svn/' to classloader
[junit4] 2> 381561 T733 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-003/collection1/lib/classes/' to classloader
[junit4] 2> 381562 T733 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-003/collection1/lib/README' to classloader
[junit4] 2> 381613 T733 oasc.SolrConfig.<init> Using Lucene MatchVersion: 5.0.0
[junit4] 2> 381628 T733 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 381633 T733 oass.IndexSchema.readSchema Reading Solr Schema from /configs/conf1/schema.xml
[junit4] 2> 381638 T733 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 381774 T733 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 381775 T733 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 381776 T733 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 381799 T733 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 381859 T733 oasc.CoreContainer.create Creating SolrCore 'collection1' using configuration from collection collection1
[junit4] 2> 381860 T733 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 381860 T733 oasc.SolrCore.<init> [collection1] Opening new SolrCore at ../../../../../../../../../Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-003/collection1/, dataDir=/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty1/
[junit4] 2> 381860 T733 oasc.SolrCore.<init> JMX monitoring not detected for core: collection1
[junit4] 2> 381861 T733 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty1
[junit4] 2> 381862 T733 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty1/index/
[junit4] 2> 381862 T733 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty1/index' doesn't exist. Creating new index...
[junit4] 2> 381863 T733 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty1/index
[junit4] 2> 381864 T733 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=12, maxMergeAtOnceExplicit=14, maxMergedSegmentMB=36.8740234375, floorSegmentMB=0.587890625, forceMergeDeletesPctAllowed=20.112168822910203, segmentsPerTier=39.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 381865 T733 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory(id=lucene-5cf19bb6)),segFN=segments_1,generation=1}
[junit4] 2> 381865 T733 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 381866 T733 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "convert-ttl-defaults"
[junit4] 2> 381866 T733 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "convert-ttl-field"
[junit4] 2> 381866 T733 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "convert-ttl-param"
[junit4] 2> 381867 T733 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "convert-ttl-field-with-param-default"
[junit4] 2> 381867 T733 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "scheduled-delete" (default)
[junit4] 2> 381867 T733 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "scheduled-delete" (default)
[junit4] 2> 381868 T733 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 381869 T733 oasc.RequestHandlers.initHandlersFromConfig created /update/json: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 381869 T733 oasc.RequestHandlers.initHandlersFromConfig created /update/json/docs: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 381869 T733 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 381869 T733 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 381870 T733 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 381870 T733 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
[junit4] 2> 381870 T733 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 381870 T733 oasc.RequestHandlers.initHandlersFromConfig created /admin/: solr.admin.AdminHandlers
[junit4] 2> 381878 T733 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 381880 T733 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 381881 T733 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 381884 T733 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 381887 T733 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 381888 T733 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 381889 T733 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=25, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 381889 T733 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory(id=lucene-5cf19bb6)),segFN=segments_1,generation=1}
[junit4] 2> 381890 T733 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 381890 T733 oass.SolrIndexSearcher.<init> Opening Searcher@c7ed6d1[collection1] main
[junit4] 2> 381890 T733 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 381894 T733 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper
[junit4] 2> 381894 T733 oasr.ManagedResourceStorage.newStorageIO Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1
[junit4] 2> 381896 T733 oasr.ManagedResourceStorage$ZooKeeperStorageIO.configure Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 381896 T733 oasr.RestManager.init Initializing RestManager with initArgs: {}
[junit4] 2> 381896 T733 oasr.ManagedResourceStorage.load Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 381906 T733 oasr.ManagedResourceStorage$ZooKeeperStorageIO.openInputStream Read 38 bytes from znode /configs/conf1/_rest_managed.json
[junit4] 2> 381907 T733 oasr.ManagedResourceStorage.load Loaded LinkedHashMap at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 381907 T733 oasr.ManagedResource.reloadFromStorage Loaded initArgs {} for /rest/managed
[junit4] 2> 381907 T733 oasr.RestManager.init Initializing 0 registered ManagedResources
[junit4] 2> 381912 T733 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 381912 T734 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c7ed6d1[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 381914 T738 oasc.ZkController.register Register replica - core:collection1 address:https://127.0.0.1:55444 collection:collection1 shard:shard2
[junit4] 2> 381916 T679 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0
[junit4] 2> 381916 T679 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 381931 T738 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4] 2> 381958 T738 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard2
[junit4] 2> 381961 T708 oasc.DistributedQueue$LatchWatcher.process NodeChildrenChanged fired on path /overseer/queue state SyncConnected
[junit4] 2> 381965 T738 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 381966 T738 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> ASYNC NEW_CORE C369 name=collection1 org.apache.solr.core.SolrCore@4115b359 url=https://127.0.0.1:55444/collection1 node=127.0.0.1:55444_ C369_STATE=coll:collection1 core:collection1 props:{core=collection1, base_url=https://127.0.0.1:55444, node_name=127.0.0.1:55444_, state=down}
[junit4] 2> 381966 T738 C369 P55444 oasc.SyncStrategy.sync Sync replicas to https://127.0.0.1:55444/collection1/
[junit4] 2> 381966 T738 C369 P55444 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 381967 T738 C369 P55444 oasc.SyncStrategy.syncToMe https://127.0.0.1:55444/collection1/ has no replicas
[junit4] 2> 381967 T738 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: https://127.0.0.1:55444/collection1/ shard2
[junit4] 2> 381967 T738 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4] 2> 382011 T704 oasc.Overseer$ClusterStateUpdater.updateZkStates going to update_collection /collections/collection1/state.json
[junit4] 2> 382017 T732 oascc.ZkStateReader$7.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json, has occurred - updating...
[junit4] 2> 382019 T732 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 2
[junit4] 2> 382079 T708 oasc.DistributedQueue$LatchWatcher.process NodeChildrenChanged fired on path /overseer/queue state SyncConnected
[junit4] 2> 382080 T704 oasc.Overseer$ClusterStateUpdater.updateZkStates going to update_collection /collections/collection1/state.json
[junit4] 2> 382081 T732 oascc.ZkStateReader$7.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json, has occurred - updating...
[junit4] 2> 382082 T732 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 3
[junit4] 2> 382121 T738 oasc.ZkController.register We are https://127.0.0.1:55444/collection1/ and leader is https://127.0.0.1:55444/collection1/
[junit4] 2> 382122 T738 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=https://127.0.0.1:55444
[junit4] 2> 382123 T738 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 382123 T738 oasc.ZkController.publish publishing core=collection1 state=active collection=collection1
[junit4] 2> 382123 T738 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 382136 T708 oasc.DistributedQueue$LatchWatcher.process NodeChildrenChanged fired on path /overseer/queue state SyncConnected
[junit4] 2> 382153 T704 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "core":"collection1",
[junit4] 2> "core_node_name":"core_node1",
[junit4] 2> "roles":null,
[junit4] 2> "base_url":"https://127.0.0.1:55444",
[junit4] 2> "node_name":"127.0.0.1:55444_",
[junit4] 2> "numShards":"2",
[junit4] 2> "state":"active",
[junit4] 2> "shard":"shard2",
[junit4] 2> "collection":"collection1",
[junit4] 2> "operation":"state"}
[junit4] 2> 382183 T738 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 3
[junit4] 2> 382195 T704 oasc.Overseer$ClusterStateUpdater.updateZkStates going to update_collection /collections/collection1/state.json
[junit4] 2> 382197 T732 oascc.ZkStateReader$7.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json, has occurred - updating...
[junit4] 2> 382202 T732 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 4
[junit4] 2> ASYNC NEW_CORE C370 name=collection1 org.apache.solr.core.SolrCore@11ec57e9 url=https://127.0.0.1:55439/collection1 node=127.0.0.1:55439_ C370_STATE=coll:control_collection core:collection1 props:{core=collection1, base_url=https://127.0.0.1:55439, node_name=127.0.0.1:55439_, state=active, leader=true}
[junit4] 2> 383192 T710 C370 P55439 oasup.DocExpirationUpdateProcessorFactory$DeleteExpiredDocsRunnable.run Begining periodic deletion of expired docs
[junit4] 2> 383193 T710 C370 P55439 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
[junit4] 2> 383194 T710 C370 P55439 oasc.SolrCore.openNewSearcher SolrIndexSearcher has not changed - not re-opening: org.apache.solr.search.SolrIndexSearcher
[junit4] 2> 383194 T710 C370 P55439 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 383194 T710 C370 P55439 oasup.LogUpdateProcessor.finish [collection1] {deleteByQuery={!cache=false}eXpField_tdt:[* TO 2014-11-02T10:17:09.484Z] (-1483654749995663360),commit=} 0 2
[junit4] 2> 383194 T710 C370 P55439 oasup.DocExpirationUpdateProcessorFactory$DeleteExpiredDocsRunnable.run Finished periodic deletion of expired docs
[junit4] 2> 383895 T679 oasc.AbstractFullDistribZkTestBase.createJettys create jetty 2
[junit4] 2> 383896 T679 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 383903 T679 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2] of [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
[junit4] 2> 383905 T679 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:55447
[junit4] 2> 383908 T679 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 383908 T679 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 383908 T679 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-004
[junit4] 2> 383909 T679 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-004/'
[junit4] 2> 383951 T679 oasc.ConfigSolr.fromFile Loading container configuration from /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-004/solr.xml
[junit4] 2> 383978 T679 oasc.CoreContainer.<init> New CoreContainer 1007408559
[junit4] 2> 383979 T679 oasc.CoreContainer.load Loading cores into CoreContainer [instanceDir=/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-004/]
[junit4] 2> 383979 T679 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 90000
[junit4] 2> 383979 T679 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to:
[junit4] 2> 383980 T679 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4] 2> 383980 T679 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4] 2> 383980 T679 oashc.HttpShardHandlerFactory.getParameter Setting maxConnections to: 10000
[junit4] 2> 383980 T679 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4] 2> 383980 T679 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4] 2> 383981 T679 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4] 2> 383981 T679 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4] 2> 383981 T679 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4] 2> 383984 T679 oasu.UpdateShardHandler.<init> Creating UpdateShardHandler HTTP client with params: socketTimeout=340000&connTimeout=45000&retry=false
[junit4] 2> 383988 T679 oasl.LogWatcher.createWatcher SLF4J impl is org.slf4j.impl.Log4jLoggerFactory
[junit4] 2> 383988 T679 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener [Log4j (org.slf4j.impl.Log4jLoggerFactory)]
[junit4] 2> 383988 T679 oasc.CoreContainer.load Host Name: 127.0.0.1
[junit4] 2> 383988 T679 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55435/solr
[junit4] 2> 383989 T679 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4] 2> 383989 T679 oascc.SolrZkClient.createZkCredentialsToAddAutomatically Using default ZkCredentialsProvider
[junit4] 2> 383990 T679 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 383996 T749 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@215bcd07 name:ZooKeeperConnection Watcher:127.0.0.1:55435 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 383996 T679 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 383997 T679 oascc.SolrZkClient.createZkACLProvider Using default ZkACLProvider
[junit4] 2> 384006 T679 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4] 2> 384014 T751 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@520ee61e name:ZooKeeperConnection Watcher:127.0.0.1:55435/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4] 2> 384014 T679 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4] 2> 384040 T679 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4] 2> ASYNC NEW_CORE C371 name=collection1 org.apache.solr.core.SolrCore@4115b359 url=https://127.0.0.1:55444/collection1 node=127.0.0.1:55444_ C371_STATE=coll:collection1 core:collection1 props:{core=collection1, base_url=https://127.0.0.1:55444, node_name=127.0.0.1:55444_, state=active, leader=true}
[junit4] 2> 384911 T735 C371 P55444 oasup.DocExpirationUpdateProcessorFactory.iAmInChargeOfPeriodicDeletes WARN Slice in charge of periodic deletes for collection1 does not currently have a leader
[junit4] 2> 385055 T679 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55447_
[junit4] 2> 385058 T679 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55447_
[junit4] 2> 385085 T679 oasc.Overseer.close Overseer (id=null) closing
[junit4] 2> 385104 T753 oasc.ZkController.publish publishing core=collection1 state=down collection=collection1
[junit4] 2> 385104 T753 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 385109 T708 oasc.DistributedQueue$LatchWatcher.process NodeChildrenChanged fired on path /overseer/queue state SyncConnected
[junit4] 2> 385120 T753 oasc.ZkController.preRegister Registering watch for external collection collection1
[junit4] 2> 385120 T753 oascc.ZkStateReader.addZkWatch addZkWatch collection1
[junit4] 2> 385122 T753 oascc.ZkStateReader.addZkWatch Updating collection state at /collections/collection1/state.json from ZooKeeper...
[junit4] 2> 385125 T753 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 4
[junit4] 2> 385126 T753 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4] 2> 385132 T704 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "core":"collection1",
[junit4] 2> "roles":null,
[junit4] 2> "base_url":"https://127.0.0.1:55447",
[junit4] 2> "node_name":"127.0.0.1:55447_",
[junit4] 2> "numShards":"2",
[junit4] 2> "state":"down",
[junit4] 2> "shard":null,
[junit4] 2> "collection":"collection1",
[junit4] 2> "operation":"state"}
[junit4] 2> 385144 T704 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4] 2> 385147 T704 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4] 2> 385160 T704 oasc.Overseer$ClusterStateUpdater.updateZkStates going to update_collection /collections/collection1/state.json
[junit4] 2> 385163 T732 oascc.ZkStateReader$7.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json, has occurred - updating...
[junit4] 2> 385164 T732 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 5
[junit4] 2> 385164 T752 oascc.ZkStateReader$7.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json, has occurred - updating...
[junit4] 2> 385166 T752 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 5
[junit4] 2> 386127 T753 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4] 2> 386128 T753 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4] 2> 386129 T753 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4] 2> 386130 T753 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 386133 T753 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper
[junit4] 2> 386133 T753 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-004/collection1/'
[junit4] 2> 386134 T753 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-004/collection1/lib/.svn/' to classloader
[junit4] 2> 386135 T753 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-004/collection1/lib/classes/' to classloader
[junit4] 2> 386135 T753 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-004/collection1/lib/README' to classloader
[junit4] 2> ASYNC NEW_CORE C372 name=collection1 org.apache.solr.core.SolrCore@11ec57e9 url=https://127.0.0.1:55439/collection1 node=127.0.0.1:55439_ C372_STATE=coll:control_collection core:collection1 props:{core=collection1, base_url=https://127.0.0.1:55439, node_name=127.0.0.1:55439_, state=active, leader=true}
[junit4] 2> 386427 T710 C372 P55439 oasup.DocExpirationUpdateProcessorFactory$DeleteExpiredDocsRunnable.run Begining periodic deletion of expired docs
[junit4] 2> 386427 T753 oasc.SolrConfig.<init> Using Lucene MatchVersion: 5.0.0
[junit4] 2> 386440 T753 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4] 2> 386441 T710 C372 P55439 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
[junit4] 2> 386452 T710 C372 P55439 oasc.SolrCore.openNewSearcher SolrIndexSearcher has not changed - not re-opening: org.apache.solr.search.SolrIndexSearcher
[junit4] 2> 386455 T753 oass.IndexSchema.readSchema Reading Solr Schema from /configs/conf1/schema.xml
[junit4] 2> 386475 T710 C372 P55439 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4] 2> 386476 T710 C372 P55439 oasup.LogUpdateProcessor.finish [collection1] {deleteByQuery={!cache=false}eXpField_tdt:[* TO 2014-11-02T10:17:12.719Z] (-1483654753386758144),commit=} 0 49
[junit4] 2> 386476 T710 C372 P55439 oasup.DocExpirationUpdateProcessorFactory$DeleteExpiredDocsRunnable.run Finished periodic deletion of expired docs
[junit4] 2> 386483 T753 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4] 2> 386627 T753 oass.IndexSchema.readSchema default search field in schema is text
[junit4] 2> 386628 T753 oass.IndexSchema.readSchema unique key field: id
[junit4] 2> 386630 T753 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 386641 T753 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4] 2> 386709 T753 oasc.CoreContainer.create Creating SolrCore 'collection1' using configuration from collection collection1
[junit4] 2> 386710 T753 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4] 2> 386711 T753 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-004/collection1/, dataDir=/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty2/
[junit4] 2> 386711 T753 oasc.SolrCore.<init> JMX monitoring not detected for core: collection1
[junit4] 2> 386711 T753 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty2
[junit4] 2> 386712 T753 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty2/index/
[junit4] 2> 386712 T753 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty2/index' doesn't exist. Creating new index...
[junit4] 2> 386712 T753 oasc.CachingDirectoryFactory.get return new directory for /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty2/index
[junit4] 2> 386712 T753 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.TieredMergePolicy: [TieredMergePolicy: maxMergeAtOnce=12, maxMergeAtOnceExplicit=14, maxMergedSegmentMB=36.8740234375, floorSegmentMB=0.587890625, forceMergeDeletesPctAllowed=20.112168822910203, segmentsPerTier=39.0, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0
[junit4] 2> 386713 T753 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory(id=lucene-415c276d)),segFN=segments_1,generation=1}
[junit4] 2> 386714 T753 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 386715 T753 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "convert-ttl-defaults"
[junit4] 2> 386720 T753 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "convert-ttl-field"
[junit4] 2> 386729 T753 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "convert-ttl-param"
[junit4] 2> 386730 T753 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "convert-ttl-field-with-param-default"
[junit4] 2> 386730 T753 oasup.UpdateRequestProcessorChain.init creating updateRequestProcessorChain "scheduled-delete" (default)
[junit4] 2> 386733 T753 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "scheduled-delete" (default)
[junit4] 2> 386733 T753 oasc.RequestHandlers.initHandlersFromConfig created /update/csv: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 386734 T753 oasc.RequestHandlers.initHandlersFromConfig created /update/json: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 386734 T753 oasc.RequestHandlers.initHandlersFromConfig created /update/json/docs: org.apache.solr.handler.UpdateRequestHandler
[junit4] 2> 386737 T753 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4] 2> 386737 T753 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4] 2> 386738 T753 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4] 2> 386738 T753 oasc.RequestHandlers.initHandlersFromConfig created /select: solr.SearchHandler
[junit4] 2> 386739 T753 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4] 2> 386739 T753 oasc.RequestHandlers.initHandlersFromConfig created /admin/: solr.admin.AdminHandlers
[junit4] 2> 386750 T753 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 386752 T753 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 386753 T753 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 386754 T753 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4] 2> 386760 T753 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4] 2> 386760 T753 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4] 2> 386760 T753 oasu.RandomMergePolicy.<init> RandomMergePolicy wrapping class org.apache.lucene.index.LogByteSizeMergePolicy: [LogByteSizeMergePolicy: minMergeSize=1677721, mergeFactor=25, maxMergeSize=2147483648, maxMergeSizeForForcedMerge=9223372036854775807, calibrateSizeByDeletes=true, maxMergeDocs=2147483647, maxCFSSegmentSizeMB=8.796093022207999E12, noCFSRatio=1.0]
[junit4] 2> 386761 T753 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4] 2> commit{dir=MockDirectoryWrapper(RAMDirectory(id=lucene-415c276d)),segFN=segments_1,generation=1}
[junit4] 2> 386761 T753 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4] 2> 386761 T753 oass.SolrIndexSearcher.<init> Opening Searcher@37575cea[collection1] main
[junit4] 2> 386762 T753 oascc.ZkStateReader.readConfigName Load collection config from:/collections/collection1
[junit4] 2> 386764 T753 oascc.ZkStateReader.readConfigName path=/collections/collection1 configName=conf1 specified config exists in ZooKeeper
[junit4] 2> 386764 T753 oasr.ManagedResourceStorage.newStorageIO Setting up ZooKeeper-based storage for the RestManager with znodeBase: /configs/conf1
[junit4] 2> 386765 T753 oasr.ManagedResourceStorage$ZooKeeperStorageIO.configure Configured ZooKeeperStorageIO with znodeBase: /configs/conf1
[junit4] 2> 386766 T753 oasr.RestManager.init Initializing RestManager with initArgs: {}
[junit4] 2> 386766 T753 oasr.ManagedResourceStorage.load Reading _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 386769 T753 oasr.ManagedResourceStorage$ZooKeeperStorageIO.openInputStream Read 38 bytes from znode /configs/conf1/_rest_managed.json
[junit4] 2> 386770 T753 oasr.ManagedResourceStorage.load Loaded LinkedHashMap at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/conf1
[junit4] 2> 386770 T753 oasr.ManagedResource.reloadFromStorage Loaded initArgs {} for /rest/managed
[junit4] 2> 386770 T753 oasr.RestManager.init Initializing 0 registered ManagedResources
[junit4] 2> 386772 T753 oasc.CoreContainer.registerCore registering core: collection1
[junit4] 2> 386772 T754 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@37575cea[collection1] main{ExitableDirectoryReader(UninvertingDirectoryReader())}
[junit4] 2> 386774 T758 oasc.ZkController.register Register replica - core:collection1 address:https://127.0.0.1:55447 collection:collection1 shard:shard1
[junit4] 2> 386777 T679 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0
[junit4] 2> 386778 T679 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4] 2> 386779 T758 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4] 2> 386788 T758 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4] 2> 386792 T708 oasc.DistributedQueue$LatchWatcher.process NodeChildrenChanged fired on path /overseer/queue state SyncConnected
[junit4] 2> 386798 T758 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4] 2> 386799 T758 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4] 2> ASYNC NEW_CORE C373 name=collection1 org.apache.solr.core.SolrCore@3f3cd845 url=https://127.0.0.1:55447/collection1 node=127.0.0.1:55447_ C373_STATE=coll:collection1 core:collection1 props:{core=collection1, base_url=https://127.0.0.1:55447, node_name=127.0.0.1:55447_, state=down}
[junit4] 2> 386799 T758 C373 P55447 oasc.SyncStrategy.sync Sync replicas to https://127.0.0.1:55447/collection1/
[junit4] 2> 386800 T758 C373 P55447 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4] 2> 386800 T758 C373 P55447 oasc.SyncStrategy.syncToMe https://127.0.0.1:55447/collection1/ has no replicas
[junit4] 2> 386800 T758 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: https://127.0.0.1:55447/collection1/ shard1
[junit4] 2> 386800 T758 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4] 2> 386823 T704 oasc.Overseer$ClusterStateUpdater.updateZkStates going to update_collection /collections/collection1/state.json
[junit4] 2> 386827 T752 oascc.ZkStateReader$7.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json, has occurred - updating...
[junit4] 2> 386827 T732 oascc.ZkStateReader$7.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json, has occurred - updating...
[junit4] 2> 386830 T752 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 6
[junit4] 2> 386830 T732 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 6
[junit4] 2> 386860 T708 oasc.DistributedQueue$LatchWatcher.process NodeChildrenChanged fired on path /overseer/queue state SyncConnected
[junit4] 2> 386865 T704 oasc.Overseer$ClusterStateUpdater.updateZkStates going to update_collection /collections/collection1/state.json
[junit4] 2> 386867 T732 oascc.ZkStateReader$7.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json, has occurred - updating...
[junit4] 2> 386878 T752 oascc.ZkStateReader$7.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json, has occurred - updating...
[junit4] 2> 386880 T752 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 7
[junit4] 2> 386881 T732 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 7
[junit4] 2> 386890 T758 oasc.ZkController.register We are https://127.0.0.1:55447/collection1/ and leader is https://127.0.0.1:55447/collection1/
[junit4] 2> 386891 T758 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=https://127.0.0.1:55447
[junit4] 2> 386891 T758 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4] 2> 386891 T758 oasc.ZkController.publish publishing core=collection1 state=active collection=collection1
[junit4] 2> 386891 T758 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4] 2> 386902 T708 oasc.DistributedQueue$LatchWatcher.process NodeChildrenChanged fired on path /overseer/queue state SyncConnected
[junit4] 2> 386918 T704 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4] 2> "core":"collection1",
[junit4] 2> "core_node_name":"core_node2",
[junit4] 2> "roles":null,
[junit4] 2> "base_url":"https://127.0.0.1:55447",
[junit4] 2> "node_name":"127.0.0.1:55447_",
[junit4] 2> "numShards":"2",
[junit4] 2> "state":"active",
[junit4] 2> "shard":"shard1",
[junit4] 2> "collection":"collection1",
[junit4] 2> "operation":"state"}
[junit4] 2> 386932 T758 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 7
[junit4] 2> 386936 T704 oasc.Overseer$ClusterStateUpdater.updateZkStates going to update_collection /collections/collection1/state.json
[junit4] 2> 386939 T732 oascc.ZkStateReader$7.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json, has occurred - updating...
[junit4] 2> 386942 T752 oascc.ZkStateReader$7.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/collections/collection1/state.json, has occurred - updating...
[junit4] 2> 386944 T752 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 8
[junit4] 2> 386944 T732 oascc.ZkStateReader.updateWatchedCollection Updating data for collection1 to ver 8
[junit4] 2> ASYNC NEW_CORE C374 name=collection1 org.apache.solr.core.SolrCore@4115b359 url=https://127.0.0.1:55444/collection1 node=127.0.0.1:55444_ C374_STATE=coll:collection1 core:collection1 props:{core=collection1, base_url=https://127.0.0.1:55444, node_name=127.0.0.1:55444_, state=active, leader=true}
[junit4] 2> 387912 T735 C374 P55444 oasup.DocExpirationUpdateProcessorFactory.iAmInChargeOfPeriodicDeletes Not currently in charge of periodic deletes for this collection, will not trigger delete or log again until this changes
[junit4] 2> 388848 T679 oasc.AbstractFullDistribZkTestBase.createJettys create jetty 3
[junit4] 2> 388849 T679 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4] 2> 388860 T679 oejus.SslContextFactory.doStart Enabled Protocols [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2] of [SSLv2Hello, SSLv3, TLSv1, TLSv1.1, TLSv1.2]
[junit4] 2> 388867 T679 oejs.AbstractConnector.doStart Started SslSelectChannelConnector@127.0.0.1:55450
[junit4] 2> 388871 T679 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4] 2> 388872 T679 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4] 2> 388872 T679 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.Dis
[...truncated too long message...]
64 T679 C426 P55458 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4] 2> 606168 T679 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4] 2> 606169 T679 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4] 2> 606169 T679 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty4/index.20141102171725268 [CachedDir<<refCount=0;path=/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty4/index.20141102171725268;done=false>>]
[junit4] 2> 606169 T679 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty4/index.20141102171725268
[junit4] 2> 606170 T679 oasc.CachingDirectoryFactory.closeCacheValue looking to close /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty4 [CachedDir<<refCount=0;path=/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty4;done=false>>]
[junit4] 2> 606170 T679 oasc.CachingDirectoryFactory.close Closing directory: /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001/tempDir-001/jetty4
[junit4] 2> 606170 T679 oasup.DocExpirationUpdateProcessorFactory$2.postClose Triggering hard close of DocExpiration Executor
[junit4] 2> 606171 T805 C426 P55458 oasup.LogUpdateProcessor.finish [collection1] {} 0 2652
[junit4] 2> 606171 T805 C426 P55458 oasup.DocExpirationUpdateProcessorFactory$DeleteExpiredDocsRunnable.run ERROR Runtime error in periodic deletion of expired docs: Exception finding leader for shard shard2 org.apache.solr.common.SolrException: Exception finding leader for shard shard2
[junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.doDeleteByQuery(DistributedUpdateProcessor.java:1409)
[junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.processDelete(DistributedUpdateProcessor.java:1275)
[junit4] 2> at org.apache.solr.update.processor.LogUpdateProcessor.processDelete(LogUpdateProcessorFactory.java:125)
[junit4] 2> at org.apache.solr.update.processor.UpdateRequestProcessor.processDelete(UpdateRequestProcessor.java:55)
[junit4] 2> at org.apache.solr.update.processor.DocExpirationUpdateProcessorFactory$DeleteExpiredDocsRunnable.run(DocExpirationUpdateProcessorFactory.java:407)
[junit4] 2> at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
[junit4] 2> at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:308)
[junit4] 2> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$301(ScheduledThreadPoolExecutor.java:180)
[junit4] 2> at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:294)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit4] 2> at java.lang.Thread.run(Thread.java:745)
[junit4] 2> Caused by: java.lang.InterruptedException: sleep interrupted
[junit4] 2> at java.lang.Thread.sleep(Native Method)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.getLeaderRetry(ZkStateReader.java:646)
[junit4] 2> at org.apache.solr.common.cloud.ZkStateReader.getLeaderRetry(ZkStateReader.java:631)
[junit4] 2> at org.apache.solr.update.processor.DistributedUpdateProcessor.doDeleteByQuery(DistributedUpdateProcessor.java:1407)
[junit4] 2> ... 11 more
[junit4] 2>
[junit4] 2> 606177 T679 oasc.Overseer.close Overseer (id=92728421209866254-127.0.0.1:55458_-n_0000000004) closing
[junit4] 2> 606178 T919 oasc.Overseer$ClusterStateUpdater.run Overseer Loop exiting : 127.0.0.1:55458_
[junit4] 2> 606185 T797 oaz.ClientCnxn$EventThread.processEvent ERROR Error while calling watcher java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@61d2f0fa rejected from java.util.concurrent.ThreadPoolExecutor@f9f6e15[Shutting down, pool size = 1, active threads = 0, queued tasks = 0, completed tasks = 24]
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2047)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:823)
[junit4] 2> at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1369)
[junit4] 2> at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112)
[junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$3.process(SolrZkClient.java:263)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:522)
[junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:498)
[junit4] 2>
[junit4] 2> 606201 T679 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4] 2> 611195 T679 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4] 2> 611197 T679 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:55435 55435
[junit4] 2> 611227 T680 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:55435 55435
[junit4] 2> NOTE: reproduce with: ant test -Dtestcase=DistribDocExpirationUpdateProcessorTest -Dtests.method=testDistribSearch -Dtests.seed=E83088324E2CED55 -Dtests.slow=true -Dtests.locale=zh_HK -Dtests.timezone=Asia/Omsk -Dtests.asserts=true -Dtests.file.encoding=UTF-8
[junit4] FAILURE 239s | DistribDocExpirationUpdateProcessorTest.testDistribSearch <<<
[junit4] > Throwable #1: java.lang.AssertionError: Give up waiting for no results: q=id%3A999&rows=0&_trace=did_it_expire_yet&_stateVer_=collection1%3A15 expected:<0> but was:<1>
[junit4] > at __randomizedtesting.SeedInfo.seed([E83088324E2CED55:69D6062A39738D69]:0)
[junit4] > at org.apache.solr.cloud.DistribDocExpirationUpdateProcessorTest.waitForNoResults(DistribDocExpirationUpdateProcessorTest.java:189)
[junit4] > at org.apache.solr.cloud.DistribDocExpirationUpdateProcessorTest.doTest(DistribDocExpirationUpdateProcessorTest.java:95)
[junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:869)
[junit4] > at java.lang.Thread.run(Thread.java:745)
[junit4] 2> 611538 T679 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4] 2> NOTE: leaving temporary files on disk at: /Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build/solr-core/test/J0/temp/solr.cloud.DistribDocExpirationUpdateProcessorTest-E83088324E2CED55-001
[junit4] 2> 238529 T678 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4] 2> NOTE: test params are: codec=Asserting(Lucene50): {_version_=PostingsFormat(name=MockRandom), eXpField_tdt=PostingsFormat(name=MockRandom), tTl_s=PostingsFormat(name=Direct), id=PostingsFormat(name=Memory doPackFST= false)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=zh_HK, timezone=Asia/Omsk
[junit4] 2> NOTE: Mac OS X 10.8.5 x86_64/Oracle Corporation 1.8.0_20 (64-bit)/cpus=2,threads=1,free=26937472,total=85987328
[junit4] 2> NOTE: All tests run in this JVM: [CloudExitableDirectoryReaderTest, TestRandomFaceting, TestShardHandlerFactory, CoreAdminHandlerTest, DistributedTermsComponentTest, TestFileDictionaryLookup, TestAddFieldRealTimeGet, TestXIncludeConfig, UpdateParamsTest, TestShortCircuitedRequests, SpatialFilterTest, SSLMigrationTest, DirectUpdateHandlerTest, DocValuesMultiTest, ExternalCollectionsTest, HdfsBasicDistributedZk2Test, DocExpirationUpdateProcessorFactoryTest, DistribDocExpirationUpdateProcessorTest]
[junit4] Completed in 238.83s, 1 test, 1 failure <<< FAILURES!
[...truncated 1333 lines...]
BUILD FAILED
/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/build.xml:525: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/build.xml:473: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/build.xml:61: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/extra-targets.xml:39: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/build.xml:189: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/solr/common-build.xml:502: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/lucene/common-build.xml:1359: The following error occurred while executing this line:
/Users/jenkins/workspace/Lucene-Solr-5.x-MacOSX/lucene/common-build.xml:966: There were test failures: 441 suites, 1804 tests, 1 failure, 49 ignored (20 assumptions)
Total time: 174 minutes 56 seconds
Build step 'Invoke Ant' marked build as failure
[description-setter] Description set: Java: 64bit/jdk1.8.0 -XX:+UseCompressedOops -XX:+UseSerialGC (asserts: true)
Archiving artifacts
Recording test results
Email was triggered for: Failure - Any
Sending email for trigger: Failure - Any