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 2013/06/28 15:46:48 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/jdk1.7.0_25) - Build # 6277
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/6277/
Java: 32bit/jdk1.7.0_25 -server -XX:+UseG1GC
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:41544/zc_/collection1lastClient and got 247 from http://127.0.0.1:55587/zc_/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:41544/zc_/collection1lastClient and got 247 from http://127.0.0.1:55587/zc_/collection1
at __randomizedtesting.SeedInfo.seed([31DBD35871971BC9:B03D5D4006C87BF5]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
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.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
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:70)
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:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
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 org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
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:358)
at java.lang.Thread.run(Thread.java:724)
Build Log:
[...truncated 9759 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 670216 T2495 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /zc_/
[junit4:junit4] 2> 670221 T2495 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1372426671468
[junit4:junit4] 2> 670221 T2495 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 670222 T2496 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 670322 T2495 oasc.ZkTestServer.run start zk server on port:43269
[junit4:junit4] 2> 670323 T2495 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 670624 T2502 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1fefb0e name:ZooKeeperConnection Watcher:127.0.0.1:43269 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 670625 T2495 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 670625 T2495 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 670628 T2495 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 670629 T2504 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@18a815e name:ZooKeeperConnection Watcher:127.0.0.1:43269/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 670629 T2495 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 670629 T2495 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 670631 T2495 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 670632 T2495 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 670633 T2495 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 670635 T2495 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 670635 T2495 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 670638 T2495 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 670638 T2495 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 670640 T2495 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 670640 T2495 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 670642 T2495 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 670642 T2495 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 670644 T2495 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 670644 T2495 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 670646 T2495 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 670646 T2495 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 670648 T2495 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 670648 T2495 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 670650 T2495 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 670650 T2495 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 670652 T2495 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 670653 T2495 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 670749 T2495 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 670751 T2495 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59612
[junit4:junit4] 2> 670752 T2495 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 670752 T2495 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 670753 T2495 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372426671902
[junit4:junit4] 2> 670753 T2495 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372426671902/solr.xml
[junit4:junit4] 2> 670753 T2495 oasc.CoreContainer.<init> New CoreContainer 16112482
[junit4:junit4] 2> 670754 T2495 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372426671902/'
[junit4:junit4] 2> 670754 T2495 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372426671902/'
[junit4:junit4] 2> 670797 T2495 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 670797 T2495 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 670797 T2495 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 670798 T2495 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 670798 T2495 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 670798 T2495 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 670799 T2495 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 670799 T2495 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 670799 T2495 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 670800 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 670802 T2495 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 670803 T2495 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43269/solr
[junit4:junit4] 2> 670803 T2495 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 670804 T2495 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 670805 T2515 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@dca22f name:ZooKeeperConnection Watcher:127.0.0.1:43269 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 670806 T2495 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 670808 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 670810 T2495 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 670811 T2517 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@601d0f name:ZooKeeperConnection Watcher:127.0.0.1:43269/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 670811 T2495 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 670812 T2495 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 670815 T2495 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 670816 T2495 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 670818 T2495 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59612_zc_
[junit4:junit4] 2> 670818 T2495 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59612_zc_
[junit4:junit4] 2> 670820 T2495 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 670823 T2495 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 670825 T2495 oasc.Overseer.start Overseer (id=89943354341457923-127.0.0.1:59612_zc_-n_0000000000) starting
[junit4:junit4] 2> 670827 T2495 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 670829 T2519 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 670829 T2495 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 670831 T2495 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 670833 T2495 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 670835 T2518 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 670839 T2520 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 670839 T2520 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 672339 T2518 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 672341 T2518 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59612_zc_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59612/zc_"}
[junit4:junit4] 2> 672341 T2518 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 672341 T2518 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 672346 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 672842 T2520 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372426671902/collection1
[junit4:junit4] 2> 672842 T2520 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 672843 T2520 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 672843 T2520 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 672844 T2520 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372426671902/collection1/'
[junit4:junit4] 2> 672844 T2520 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372426671902/collection1/lib/README' to classloader
[junit4:junit4] 2> 672845 T2520 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372426671902/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 672871 T2520 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 672902 T2520 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 672904 T2520 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 672908 T2520 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 673263 T2520 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 673264 T2520 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 673266 T2520 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 673274 T2520 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 673277 T2520 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 673287 T2520 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 673290 T2520 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 673292 T2520 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 673293 T2520 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 673293 T2520 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 673293 T2520 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 673294 T2520 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 673294 T2520 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 673294 T2520 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 673295 T2520 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372426671902/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372426671468/control/data/
[junit4:junit4] 2> 673295 T2520 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@123c852
[junit4:junit4] 2> 673295 T2520 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 673296 T2520 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/control/data
[junit4:junit4] 2> 673296 T2520 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372426671468/control/data/index/
[junit4:junit4] 2> 673296 T2520 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372426671468/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 673296 T2520 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/control/data/index
[junit4:junit4] 2> 673299 T2520 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@181f0f6; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 673300 T2520 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 673301 T2520 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 673302 T2520 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 673302 T2520 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 673302 T2520 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 673303 T2520 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 673303 T2520 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 673303 T2520 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 673304 T2520 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 673304 T2520 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 673306 T2520 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 673309 T2520 oass.SolrIndexSearcher.<init> Opening Searcher@dea80e main
[junit4:junit4] 2> 673309 T2520 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 673309 T2520 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 673314 T2521 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@dea80e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 673316 T2520 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 673316 T2520 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59612/zc_ collection:control_collection shard:shard1
[junit4:junit4] 2> 673317 T2520 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 673321 T2520 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 673323 T2520 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 673323 T2520 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 673323 T2520 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:59612/zc_/collection1/
[junit4:junit4] 2> 673324 T2520 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 673324 T2520 oasc.SyncStrategy.syncToMe http://127.0.0.1:59612/zc_/collection1/ has no replicas
[junit4:junit4] 2> 673324 T2520 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:59612/zc_/collection1/
[junit4:junit4] 2> 673324 T2520 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 673851 T2518 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 673859 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 673879 T2520 oasc.ZkController.register We are http://127.0.0.1:59612/zc_/collection1/ and leader is http://127.0.0.1:59612/zc_/collection1/
[junit4:junit4] 2> 673879 T2520 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59612/zc_
[junit4:junit4] 2> 673880 T2520 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 673880 T2520 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 673880 T2520 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 673882 T2520 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 673883 T2495 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 673884 T2495 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 673885 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 673890 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 673892 T2495 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 673894 T2524 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7558f5 name:ZooKeeperConnection Watcher:127.0.0.1:43269/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 673895 T2495 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 673896 T2495 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 673899 T2495 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 673979 T2495 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 673981 T2495 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:41544
[junit4:junit4] 2> 673982 T2495 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 673982 T2495 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 673982 T2495 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372426675147
[junit4:junit4] 2> 673983 T2495 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372426675147/solr.xml
[junit4:junit4] 2> 673983 T2495 oasc.CoreContainer.<init> New CoreContainer 12388664
[junit4:junit4] 2> 673983 T2495 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372426675147/'
[junit4:junit4] 2> 673984 T2495 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372426675147/'
[junit4:junit4] 2> 674026 T2495 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 674026 T2495 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 674026 T2495 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 674027 T2495 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 674027 T2495 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 674027 T2495 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 674028 T2495 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 674028 T2495 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 674028 T2495 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 674029 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 674031 T2495 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 674032 T2495 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43269/solr
[junit4:junit4] 2> 674032 T2495 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 674033 T2495 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 674034 T2535 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b454ba name:ZooKeeperConnection Watcher:127.0.0.1:43269 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 674035 T2495 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 674037 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 674041 T2495 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 674042 T2537 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a4f391 name:ZooKeeperConnection Watcher:127.0.0.1:43269/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 674042 T2495 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 674046 T2495 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 675049 T2495 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41544_zc_
[junit4:junit4] 2> 675050 T2495 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:41544_zc_
[junit4:junit4] 2> 675052 T2524 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 675052 T2517 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 675052 T2537 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 675052 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 675056 T2538 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 675056 T2538 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 675365 T2518 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 675366 T2518 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:59612_zc_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59612/zc_"}
[junit4:junit4] 2> 675370 T2518 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:41544_zc_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41544/zc_"}
[junit4:junit4] 2> 675370 T2518 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 675370 T2518 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 675374 T2537 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 675374 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 675374 T2524 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 676057 T2538 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372426675147/collection1
[junit4:junit4] 2> 676057 T2538 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 676058 T2538 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 676058 T2538 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 676059 T2538 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372426675147/collection1/'
[junit4:junit4] 2> 676060 T2538 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372426675147/collection1/lib/README' to classloader
[junit4:junit4] 2> 676060 T2538 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372426675147/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 676087 T2538 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 676121 T2538 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 676122 T2538 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 676126 T2538 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 676485 T2538 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 676486 T2538 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 676486 T2538 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 676492 T2538 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 676495 T2538 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 676503 T2538 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 676507 T2538 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 676509 T2538 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 676509 T2538 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 676510 T2538 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 676510 T2538 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 676510 T2538 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 676511 T2538 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 676511 T2538 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 676511 T2538 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372426675147/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1/
[junit4:junit4] 2> 676511 T2538 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@123c852
[junit4:junit4] 2> 676512 T2538 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 676512 T2538 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1
[junit4:junit4] 2> 676512 T2538 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1/index/
[junit4:junit4] 2> 676512 T2538 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 676513 T2538 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1/index
[junit4:junit4] 2> 676516 T2538 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@76b39d; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 676516 T2538 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 676518 T2538 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 676518 T2538 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 676519 T2538 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 676519 T2538 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 676520 T2538 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 676520 T2538 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 676520 T2538 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 676521 T2538 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 676521 T2538 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 676524 T2538 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 676528 T2538 oass.SolrIndexSearcher.<init> Opening Searcher@1397152 main
[junit4:junit4] 2> 676528 T2538 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 676528 T2538 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 676532 T2539 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1397152 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 676534 T2538 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 676534 T2538 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:41544/zc_ collection:collection1 shard:shard1
[junit4:junit4] 2> 676535 T2538 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 676539 T2538 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 676541 T2538 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 676541 T2538 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 676541 T2538 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:41544/zc_/collection1/
[junit4:junit4] 2> 676541 T2538 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 676541 T2538 oasc.SyncStrategy.syncToMe http://127.0.0.1:41544/zc_/collection1/ has no replicas
[junit4:junit4] 2> 676542 T2538 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:41544/zc_/collection1/
[junit4:junit4] 2> 676542 T2538 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 676879 T2518 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 676883 T2524 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 676883 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 676884 T2537 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 676895 T2538 oasc.ZkController.register We are http://127.0.0.1:41544/zc_/collection1/ and leader is http://127.0.0.1:41544/zc_/collection1/
[junit4:junit4] 2> 676896 T2538 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:41544/zc_
[junit4:junit4] 2> 676896 T2538 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 676896 T2538 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 676896 T2538 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 676898 T2538 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 676898 T2495 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 676899 T2495 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 676899 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 676967 T2495 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 676969 T2495 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58230
[junit4:junit4] 2> 676970 T2495 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 676970 T2495 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 676971 T2495 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372426678149
[junit4:junit4] 2> 676971 T2495 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372426678149/solr.xml
[junit4:junit4] 2> 676971 T2495 oasc.CoreContainer.<init> New CoreContainer 5293951
[junit4:junit4] 2> 676972 T2495 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372426678149/'
[junit4:junit4] 2> 676972 T2495 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372426678149/'
[junit4:junit4] 2> 677019 T2495 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 677020 T2495 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 677020 T2495 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 677020 T2495 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 677021 T2495 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 677021 T2495 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 677021 T2495 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 677021 T2495 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 677022 T2495 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 677022 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 677025 T2495 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 677026 T2495 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43269/solr
[junit4:junit4] 2> 677026 T2495 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 677027 T2495 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 677028 T2551 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@9c67f1 name:ZooKeeperConnection Watcher:127.0.0.1:43269 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 677028 T2495 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 677029 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 677032 T2495 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 677033 T2553 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7b0045 name:ZooKeeperConnection Watcher:127.0.0.1:43269/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 677034 T2495 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 677036 T2495 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 678038 T2495 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58230_zc_
[junit4:junit4] 2> 678039 T2495 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58230_zc_
[junit4:junit4] 2> 678040 T2524 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 678040 T2517 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 678040 T2537 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 678040 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 678041 T2553 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 678041 T2537 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 678041 T2524 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 678044 T2554 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 678045 T2554 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 678387 T2518 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 678387 T2518 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:41544_zc_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41544/zc_"}
[junit4:junit4] 2> 678389 T2518 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:58230_zc_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58230/zc_"}
[junit4:junit4] 2> 678390 T2518 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 678390 T2518 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 678392 T2537 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 678392 T2553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 678392 T2524 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 678392 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 679046 T2554 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372426678149/collection1
[junit4:junit4] 2> 679046 T2554 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 679047 T2554 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 679047 T2554 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 679048 T2554 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372426678149/collection1/'
[junit4:junit4] 2> 679049 T2554 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372426678149/collection1/lib/README' to classloader
[junit4:junit4] 2> 679049 T2554 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372426678149/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 679084 T2554 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 679117 T2554 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 679119 T2554 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 679122 T2554 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 679467 T2554 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 679468 T2554 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 679469 T2554 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 679474 T2554 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 679476 T2554 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 679486 T2554 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 679488 T2554 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 679491 T2554 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 679492 T2554 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 679492 T2554 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 679492 T2554 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 679493 T2554 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 679493 T2554 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 679493 T2554 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 679493 T2554 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372426678149/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty2/
[junit4:junit4] 2> 679494 T2554 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@123c852
[junit4:junit4] 2> 679494 T2554 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 679494 T2554 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty2
[junit4:junit4] 2> 679494 T2554 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty2/index/
[junit4:junit4] 2> 679495 T2554 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 679495 T2554 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty2/index
[junit4:junit4] 2> 679498 T2554 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@c3b1cf; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 679499 T2554 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 679500 T2554 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 679501 T2554 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 679501 T2554 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 679502 T2554 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 679502 T2554 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 679502 T2554 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 679503 T2554 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 679503 T2554 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 679504 T2554 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 679506 T2554 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 679509 T2554 oass.SolrIndexSearcher.<init> Opening Searcher@1197eb7 main
[junit4:junit4] 2> 679509 T2554 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 679509 T2554 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 679513 T2555 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1197eb7 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 679515 T2554 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 679515 T2554 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58230/zc_ collection:collection1 shard:shard1
[junit4:junit4] 2> 679518 T2554 oasc.ZkController.register We are http://127.0.0.1:58230/zc_/collection1/ and leader is http://127.0.0.1:41544/zc_/collection1/
[junit4:junit4] 2> 679518 T2554 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58230/zc_
[junit4:junit4] 2> 679518 T2554 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 679518 T2554 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C895 name=collection1 org.apache.solr.core.SolrCore@aa7fc0 url=http://127.0.0.1:58230/zc_/collection1 node=127.0.0.1:58230_zc_ C895_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:58230_zc_, base_url=http://127.0.0.1:58230/zc_}
[junit4:junit4] 2> 679518 T2556 C895 P58230 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 679519 T2554 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 679519 T2556 C895 P58230 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 679519 T2556 C895 P58230 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 679519 T2556 C895 P58230 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 679520 T2495 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 679520 T2495 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 679520 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 679521 T2556 C895 P58230 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 679524 T2533 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 679586 T2495 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 679588 T2495 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55587
[junit4:junit4] 2> 679589 T2495 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 679589 T2495 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 679589 T2495 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372426680770
[junit4:junit4] 2> 679590 T2495 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372426680770/solr.xml
[junit4:junit4] 2> 679590 T2495 oasc.CoreContainer.<init> New CoreContainer 16501172
[junit4:junit4] 2> 679590 T2495 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372426680770/'
[junit4:junit4] 2> 679591 T2495 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372426680770/'
[junit4:junit4] 2> 679633 T2495 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 679634 T2495 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 679634 T2495 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 679634 T2495 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 679635 T2495 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 679635 T2495 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 679635 T2495 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 679636 T2495 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 679636 T2495 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 679636 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 679639 T2495 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 679639 T2495 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43269/solr
[junit4:junit4] 2> 679640 T2495 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 679640 T2495 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 679642 T2568 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@cf18d4 name:ZooKeeperConnection Watcher:127.0.0.1:43269 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 679643 T2495 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 679644 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 679646 T2495 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 679647 T2570 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f116e0 name:ZooKeeperConnection Watcher:127.0.0.1:43269/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 679648 T2495 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 679650 T2495 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 679897 T2518 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 679898 T2518 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:58230_zc_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58230/zc_"}
[junit4:junit4] 2> 679902 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 679903 T2570 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 679902 T2537 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 679902 T2524 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 679902 T2553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 680525 T2533 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 680525 T2533 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=3&state=recovering&nodeName=127.0.0.1:58230_zc_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 680652 T2495 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55587_zc_
[junit4:junit4] 2> 680654 T2495 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55587_zc_
[junit4:junit4] 2> 680655 T2553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 680655 T2524 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 3)
[junit4:junit4] 2> 680656 T2537 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 680656 T2517 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 680656 T2570 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 680656 T2570 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 680656 T2537 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 680656 T2553 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 680656 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 680657 T2524 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 680661 T2571 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 680661 T2571 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 681406 T2518 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 681407 T2518 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55587_zc_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55587/zc_"}
[junit4:junit4] 2> 681407 T2518 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 681408 T2518 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 681411 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 681411 T2570 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 681411 T2524 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 681411 T2537 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 681411 T2553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 681662 T2571 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372426680770/collection1
[junit4:junit4] 2> 681663 T2571 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 681664 T2571 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 681664 T2571 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 681665 T2571 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372426680770/collection1/'
[junit4:junit4] 2> 681666 T2571 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372426680770/collection1/lib/README' to classloader
[junit4:junit4] 2> 681666 T2571 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372426680770/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 681698 T2571 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 681747 T2571 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 681749 T2571 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 681752 T2571 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 682090 T2571 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 682091 T2571 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 682091 T2571 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 682097 T2571 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 682099 T2571 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 682112 T2571 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 682115 T2571 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 682118 T2571 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 682119 T2571 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 682119 T2571 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 682119 T2571 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 682120 T2571 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 682120 T2571 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 682120 T2571 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 682120 T2571 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372426680770/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty3/
[junit4:junit4] 2> 682120 T2571 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@123c852
[junit4:junit4] 2> 682121 T2571 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 682121 T2571 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty3
[junit4:junit4] 2> 682121 T2571 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty3/index/
[junit4:junit4] 2> 682122 T2571 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 682122 T2571 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty3/index
[junit4:junit4] 2> 682125 T2571 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d0f78a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 682125 T2571 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 682127 T2571 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 682127 T2571 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 682127 T2571 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 682128 T2571 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 682129 T2571 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 682129 T2571 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 682129 T2571 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 682130 T2571 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 682130 T2571 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 682132 T2571 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 682135 T2571 oass.SolrIndexSearcher.<init> Opening Searcher@1466625 main
[junit4:junit4] 2> 682135 T2571 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 682135 T2571 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 682139 T2572 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1466625 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 682141 T2571 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 682141 T2571 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55587/zc_ collection:collection1 shard:shard1
[junit4:junit4] 2> 682143 T2571 oasc.ZkController.register We are http://127.0.0.1:55587/zc_/collection1/ and leader is http://127.0.0.1:41544/zc_/collection1/
[junit4:junit4] 2> 682143 T2571 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55587/zc_
[junit4:junit4] 2> 682144 T2571 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 682144 T2571 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C896 name=collection1 org.apache.solr.core.SolrCore@4a6b8e url=http://127.0.0.1:55587/zc_/collection1 node=127.0.0.1:55587_zc_ C896_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:55587_zc_, base_url=http://127.0.0.1:55587/zc_}
[junit4:junit4] 2> 682144 T2573 C896 P55587 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 682144 T2571 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 682145 T2573 C896 P55587 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 682145 T2573 C896 P55587 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 682145 T2573 C896 P55587 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 682145 T2495 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 682146 T2573 C896 P55587 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 682146 T2495 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 682146 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 682149 T2533 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 682223 T2495 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 682225 T2495 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:36981
[junit4:junit4] 2> 682227 T2495 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 682227 T2495 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 682227 T2495 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372426683397
[junit4:junit4] 2> 682228 T2495 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372426683397/solr.xml
[junit4:junit4] 2> 682228 T2495 oasc.CoreContainer.<init> New CoreContainer 23121806
[junit4:junit4] 2> 682228 T2495 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372426683397/'
[junit4:junit4] 2> 682229 T2495 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372426683397/'
[junit4:junit4] 2> 682271 T2495 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 682272 T2495 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 682272 T2495 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 682272 T2495 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 682272 T2495 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 682273 T2495 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 682273 T2495 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 682273 T2495 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 682274 T2495 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 682274 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 682277 T2495 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 682277 T2495 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43269/solr
[junit4:junit4] 2> 682278 T2495 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 682278 T2495 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 682279 T2585 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19ff512 name:ZooKeeperConnection Watcher:127.0.0.1:43269 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 682280 T2495 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 682281 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 682283 T2495 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 682284 T2587 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@150d24a name:ZooKeeperConnection Watcher:127.0.0.1:43269/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 682285 T2495 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 682287 T2495 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C897 name=collection1 org.apache.solr.core.SolrCore@aa7fc0 url=http://127.0.0.1:58230/zc_/collection1 node=127.0.0.1:58230_zc_ C897_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:58230_zc_, base_url=http://127.0.0.1:58230/zc_}
[junit4:junit4] 2> 682526 T2556 C897 P58230 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:41544/zc_/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 682526 T2556 C897 P58230 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58230/zc_ START replicas=[http://127.0.0.1:41544/zc_/collection1/] nUpdates=100
[junit4:junit4] 2> 682527 T2556 C897 P58230 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 682527 T2556 C897 P58230 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 682527 T2556 C897 P58230 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 682527 T2556 C897 P58230 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 682528 T2556 C897 P58230 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 682528 T2556 C897 P58230 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:41544/zc_/collection1/. core=collection1
[junit4:junit4] 2> 682528 T2556 C897 P58230 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C898 name=collection1 org.apache.solr.core.SolrCore@f7f97c url=http://127.0.0.1:41544/zc_/collection1 node=127.0.0.1:41544_zc_ C898_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:41544_zc_, base_url=http://127.0.0.1:41544/zc_, leader=true}
[junit4:junit4] 2> 682532 T2531 C898 P41544 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 682536 T2530 C898 P41544 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 682539 T2530 C898 P41544 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@76b39d; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 682540 T2530 C898 P41544 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 682540 T2530 C898 P41544 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 682541 T2530 C898 P41544 oass.SolrIndexSearcher.<init> Opening Searcher@11e211a realtime
[junit4:junit4] 2> 682541 T2530 C898 P41544 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 682541 T2530 C898 P41544 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 682542 T2556 C897 P58230 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 682543 T2556 C897 P58230 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 682544 T2532 C898 P41544 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 682544 T2532 C898 P41544 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 682545 T2556 C897 P58230 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 682545 T2556 C897 P58230 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 682545 T2556 C897 P58230 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 682545 T2556 C897 P58230 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 682546 T2556 C897 P58230 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 682915 T2518 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 682915 T2518 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55587_zc_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55587/zc_"}
[junit4:junit4] 2> 682917 T2518 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:58230_zc_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58230/zc_"}
[junit4:junit4] 2> 682920 T2587 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 682920 T2553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 682921 T2570 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 682920 T2524 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 682920 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 682921 T2537 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 683150 T2533 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 683150 T2533 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:55587_zc_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 683289 T2495 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36981_zc_
[junit4:junit4] 2> 683291 T2495 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:36981_zc_
[junit4:junit4] 2> 683293 T2553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 683293 T2524 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 683293 T2537 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 683293 T2570 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 683293 T2587 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 683294 T2587 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 683294 T2570 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 683294 T2517 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 683294 T2537 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 683295 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 683295 T2553 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 683296 T2524 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 683299 T2589 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 683300 T2589 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 684424 T2518 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 684425 T2518 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:36981_zc_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:36981/zc_"}
[junit4:junit4] 2> 684425 T2518 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 684425 T2518 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 684427 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 684428 T2570 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 684428 T2524 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 684427 T2537 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 684427 T2553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 684427 T2587 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> C896_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:55587_zc_, base_url=http://127.0.0.1:55587/zc_}
[junit4:junit4] 2> 685151 T2573 C896 P55587 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:41544/zc_/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 685151 T2573 C896 P55587 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:55587/zc_ START replicas=[http://127.0.0.1:41544/zc_/collection1/] nUpdates=100
[junit4:junit4] 2> 685152 T2573 C896 P55587 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 685152 T2573 C896 P55587 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 685152 T2573 C896 P55587 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 685153 T2573 C896 P55587 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 685153 T2573 C896 P55587 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 685153 T2573 C896 P55587 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:41544/zc_/collection1/. core=collection1
[junit4:junit4] 2> 685153 T2573 C896 P55587 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 685154 T2533 C898 P41544 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 685156 T2530 C898 P41544 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 685156 T2530 C898 P41544 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 685157 T2530 C898 P41544 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 685157 T2530 C898 P41544 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 1
[junit4:junit4] 2> 685157 T2573 C896 P55587 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 685158 T2573 C896 P55587 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 685159 T2533 C898 P41544 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 685160 T2573 C896 P55587 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 685160 T2573 C896 P55587 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 685160 T2573 C896 P55587 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 685160 T2573 C896 P55587 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 685161 T2573 C896 P55587 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 685301 T2589 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372426683397/collection1
[junit4:junit4] 2> 685301 T2589 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 685302 T2589 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 685302 T2589 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 685303 T2589 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372426683397/collection1/'
[junit4:junit4] 2> 685303 T2589 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372426683397/collection1/lib/README' to classloader
[junit4:junit4] 2> 685304 T2589 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372426683397/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 685329 T2589 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 685358 T2589 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 685359 T2589 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 685363 T2589 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 685693 T2589 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 685693 T2589 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 685694 T2589 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 685699 T2589 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 685701 T2589 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 685710 T2589 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 685713 T2589 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 685717 T2589 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 685718 T2589 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 685718 T2589 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 685718 T2589 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 685719 T2589 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 685719 T2589 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 685719 T2589 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 685720 T2589 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372426683397/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty4/
[junit4:junit4] 2> 685720 T2589 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@123c852
[junit4:junit4] 2> 685720 T2589 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 685721 T2589 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty4
[junit4:junit4] 2> 685721 T2589 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty4/index/
[junit4:junit4] 2> 685721 T2589 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 685721 T2589 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty4/index
[junit4:junit4] 2> 685724 T2589 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@c37e55; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 685724 T2589 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 685726 T2589 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 685726 T2589 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 685727 T2589 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 685727 T2589 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 685728 T2589 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 685728 T2589 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 685729 T2589 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 685730 T2589 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 685730 T2589 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 685732 T2589 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 685735 T2589 oass.SolrIndexSearcher.<init> Opening Searcher@22183 main
[junit4:junit4] 2> 685735 T2589 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 685735 T2589 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 685740 T2591 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@22183 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 685742 T2589 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 685743 T2589 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:36981/zc_ collection:collection1 shard:shard1
[junit4:junit4] 2> 685745 T2589 oasc.ZkController.register We are http://127.0.0.1:36981/zc_/collection1/ and leader is http://127.0.0.1:41544/zc_/collection1/
[junit4:junit4] 2> 685745 T2589 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:36981/zc_
[junit4:junit4] 2> 685745 T2589 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 685745 T2589 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C899 name=collection1 org.apache.solr.core.SolrCore@1849921 url=http://127.0.0.1:36981/zc_/collection1 node=127.0.0.1:36981_zc_ C899_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:36981_zc_, base_url=http://127.0.0.1:36981/zc_}
[junit4:junit4] 2> 685746 T2592 C899 P36981 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 685746 T2589 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 685747 T2592 C899 P36981 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 685747 T2592 C899 P36981 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 685747 T2592 C899 P36981 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 685747 T2495 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 685748 T2495 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 685748 T2592 C899 P36981 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 685748 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 685751 T2495 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 685751 T2531 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 685752 T2495 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 685752 T2495 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 685752 T2495 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 685931 T2518 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 685932 T2518 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55587_zc_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55587/zc_"}
[junit4:junit4] 2> 685935 T2518 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:36981_zc_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:36981/zc_"}
[junit4:junit4] 2> 685937 T2553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 685937 T2570 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 685937 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 685937 T2587 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 685937 T2524 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 685937 T2537 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 686752 T2531 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 686752 T2531 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:36981_zc_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 686753 T2495 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 687755 T2495 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C899_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:36981_zc_, base_url=http://127.0.0.1:36981/zc_}
[junit4:junit4] 2> 688753 T2592 C899 P36981 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:41544/zc_/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 688754 T2592 C899 P36981 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:36981/zc_ START replicas=[http://127.0.0.1:41544/zc_/collection1/] nUpdates=100
[junit4:junit4] 2> 688754 T2592 C899 P36981 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 688755 T2592 C899 P36981 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 688755 T2592 C899 P36981 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 688755 T2592 C899 P36981 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 688755 T2592 C899 P36981 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 688755 T2592 C899 P36981 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:41544/zc_/collection1/. core=collection1
[junit4:junit4] 2> 688756 T2592 C899 P36981 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 688756 T2495 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C900 name=collection1 org.apache.solr.core.SolrCore@f7f97c url=http://127.0.0.1:41544/zc_/collection1 node=127.0.0.1:41544_zc_ C900_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:41544_zc_, base_url=http://127.0.0.1:41544/zc_, leader=true}
[junit4:junit4] 2> 688756 T2533 C900 P41544 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 688760 T2532 C900 P41544 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 688760 T2532 C900 P41544 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 688761 T2532 C900 P41544 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 688761 T2532 C900 P41544 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 1
[junit4:junit4] 2> 688762 T2592 C899 P36981 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 688762 T2592 C899 P36981 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 688764 T2531 C900 P41544 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 688764 T2592 C899 P36981 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 688764 T2592 C899 P36981 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 688764 T2592 C899 P36981 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 688765 T2592 C899 P36981 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 688766 T2592 C899 P36981 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 688943 T2518 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 688943 T2518 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:36981_zc_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:36981/zc_"}
[junit4:junit4] 2> 688947 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 688947 T2570 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 688947 T2553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 688947 T2587 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 688947 T2524 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 688947 T2537 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 689757 T2495 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 689758 T2495 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C901 name=collection1 org.apache.solr.core.SolrCore@5aa054 url=http://127.0.0.1:59612/zc_/collection1 node=127.0.0.1:59612_zc_ C901_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:59612_zc_, base_url=http://127.0.0.1:59612/zc_, leader=true}
[junit4:junit4] 2> 689763 T2511 C901 P59612 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 689765 T2511 C901 P59612 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@181f0f6; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 689766 T2511 C901 P59612 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 689766 T2511 C901 P59612 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 689766 T2511 C901 P59612 oass.SolrIndexSearcher.<init> Opening Searcher@1278766 main
[junit4:junit4] 2> 689767 T2511 C901 P59612 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 689767 T2521 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1278766 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 689768 T2511 C901 P59612 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> ASYNC NEW_CORE C902 name=collection1 org.apache.solr.core.SolrCore@aa7fc0 url=http://127.0.0.1:58230/zc_/collection1 node=127.0.0.1:58230_zc_ C902_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:58230_zc_, base_url=http://127.0.0.1:58230/zc_}
[junit4:junit4] 2> 689774 T2549 C902 P58230 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:41544/zc_/collection1/, StdNode: http://127.0.0.1:58230/zc_/collection1/, StdNode: http://127.0.0.1:55587/zc_/collection1/, StdNode: http://127.0.0.1:36981/zc_/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 689777 T2531 C900 P41544 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 689777 T2546 C902 P58230 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 689777 T2531 C900 P41544 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 689778 T2531 C900 P41544 oass.SolrIndexSearcher.<init> Opening Searcher@1771b61 main
[junit4:junit4] 2> 689778 T2531 C900 P41544 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 689779 T2539 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1771b61 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 689779 T2531 C900 P41544 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 2
[junit4:junit4] 2> 689779 T2546 C902 P58230 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@c3b1cf; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 689780 T2546 C902 P58230 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> ASYNC NEW_CORE C903 name=collection1 org.apache.solr.core.SolrCore@4a6b8e url=http://127.0.0.1:55587/zc_/collection1 node=127.0.0.1:55587_zc_ C903_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55587_zc_, base_url=http://127.0.0.1:55587/zc_}
[junit4:junit4] 2> 689780 T2566 C903 P55587 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 689781 T2546 C902 P58230 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 689782 T2546 C902 P58230 oass.SolrIndexSearcher.<init> Opening Searcher@1c3da17 main
[junit4:junit4] 2> C899_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:36981_zc_, base_url=http://127.0.0.1:36981/zc_}
[junit4:junit4] 2> 689782 T2581 C899 P36981 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 689782 T2566 C903 P55587 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d0f78a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 689783 T2555 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1c3da17 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 689782 T2546 C902 P58230 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 689783 T2566 C903 P55587 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 689783 T2546 C902 P58230 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 689784 T2581 C899 P36981 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@c37e55; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 689784 T2566 C903 P55587 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 689785 T2581 C899 P36981 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 689785 T2566 C903 P55587 oass.SolrIndexSearcher.<init> Opening Searcher@8414aa main
[junit4:junit4] 2> 689785 T2581 C899 P36981 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 689786 T2566 C903 P55587 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 689786 T2581 C899 P36981 oass.SolrIndexSearcher.<init> Opening Searcher@14bce4a main
[junit4:junit4] 2> 689787 T2581 C899 P36981 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 689787 T2572 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@8414aa main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 689787 T2591 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@14bce4a main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 689787 T2566 C903 P55587 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 689787 T2581 C899 P36981 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 689788 T2549 C902 P58230 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 14
[junit4:junit4] 2> 689789 T2495 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 689791 T2532 C900 P41544 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 689792 T2546 C902 P58230 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 689794 T2563 C903 P55587 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 689795 T2583 C899 P36981 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 691799 T2510 C901 P59612 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1439093692086353920)} 0 1
[junit4:junit4] 2> 691806 T2580 C899 P36981 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={update.distrib=FROMLEADER&_version_=-1439093692090548224&update.from=http://127.0.0.1:41544/zc_/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439093692090548224)} 0 1
[junit4:junit4] 2> 691806 T2563 C903 P55587 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={update.distrib=FROMLEADER&_version_=-1439093692090548224&update.from=http://127.0.0.1:41544/zc_/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439093692090548224)} 0 1
[junit4:junit4] 2> 691806 T2546 C902 P58230 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={update.distrib=FROMLEADER&_version_=-1439093692090548224&update.from=http://127.0.0.1:41544/zc_/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439093692090548224)} 0 1
[junit4:junit4] 2> 691807 T2532 C900 P41544 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1439093692090548224)} 0 5
[junit4:junit4] 2> 691808 T2583 C899 P36981 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={wt=javabin&version=2} {deleteByQuery=*:*} 0 7
[junit4:junit4] 2> 691811 T2511 C901 P59612 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={wt=javabin&version=2} {add=[0 (1439093692098936832)]} 0 1
[junit4:junit4] 2> 691818 T2549 C902 P58230 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={distrib.from=http://127.0.0.1:41544/zc_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1439093692104179712)]} 0 1
[junit4:junit4] 2> 691818 T2564 C903 P55587 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={distrib.from=http://127.0.0.1:41544/zc_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1439093692104179712)]} 0 0
[junit4:junit4] 2> 691819 T2581 C899 P36981 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={distrib.from=http://127.0.0.1:41544/zc_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1439093692104179712)]} 0 1
[junit4:junit4] 2> 691819 T2530 C900 P41544 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={distrib.from=http://127.0.0.1:58230/zc_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1439093692104179712)]} 0 5
[junit4:junit4] 2> 691820 T2547 C902 P58230 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={wt=javabin&version=2} {add=[0]} 0 7
[junit4:junit4] 2> 691823 T2512 C901 P59612 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={wt=javabin&version=2} {add=[1 (1439093692111519744)]} 0 1
[junit4:junit4] 2> 691832 T2548 C902 P58230 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={distrib.from=http://127.0.0.1:41544/zc_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439093692116762624)]} 0 2
[junit4:junit4] 2> 691832 T2580 C899 P36981 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={distrib.from=http://127.0.0.1:41544/zc_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439093692116762624)]} 0 2
[junit4:junit4] 2> 691832 T2565 C903 P55587 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={distrib.from=http://127.0.0.1:41544/zc_/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439093692116762624)]} 0 2
[junit4:junit4] 2> 691834 T2531 C900 P41544 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={distrib.from=http://127.0.0.1:36981/zc_/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1439093692116762624)]} 0 7
[junit4:junit4] 2> 691834 T2582 C899 P36981 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={wt=javabin&version=2} {add=[1]} 0 9
[junit4:junit4] 2> 691837 T2513 C901 P59612 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={wt=javabin&version=2} {add=[2 (1439093692126199808)]} 0 1
[junit4:junit4] 2> 691841 T2533 C900 P41544 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:58230/zc_/collection1/]
[junit4:junit4] 2> 691842 T2533 C900 P41544 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:58230/zc_/collection1/ against:[http://127.0.0.1:58230/zc_/collection1/] result:true
[junit4:junit4] 2> 691842 T2533 C900 P41544 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:55587/zc_/collection1/ against:[http://127.0.0.1:58230/zc_/collection1/] result:false
[junit4:junit4] 2> 691843 T2533 C900 P41544 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:36981/zc_/collection1/ against:[http://127.0.0.1:58230/zc_/collection1/] result:false
[junit4:junit4] 2> 691848 T2581 C899 P36981 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={distrib.from=http://127.0.0.1:41544/zc_/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:58230/zc_/collection1/&wt=javabin&version=2} {add=[2 (1439093692133539840)]} 0 2
[junit4:junit4] 2> 691848 T2566 C903 P55587 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={distrib.from=http://127.0.0.1:41544/zc_/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:58230/zc_/collection1/&wt=javabin&version=2} {add=[2 (1439093692133539840)]} 0 2
[junit4:junit4] 2> 691849 T2533 C900 P41544 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={distrib.from=http://127.0.0.1:36981/zc_/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:58230/zc_/collection1/&wt=javabin&version=2} {add=[2 (1439093692133539840)]} 0 8
[junit4:junit4] 2> 691850 T2583 C899 P36981 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={test.distrib.skip.servers=http://127.0.0.1:58230/zc_/collection1/&wt=javabin&version=2} {add=[2]} 0 11
[junit4:junit4] 2> 691853 T2510 C901 P59612 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={wt=javabin&version=2} {add=[3 (1439093692144025600)]} 0 1
[junit4:junit4] 2> 691855 T2530 C900 P41544 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:58230/zc_/collection1/, http://127.0.0.1:55587/zc_/collection1/]
[junit4:junit4] 2> 691855 T2530 C900 P41544 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:58230/zc_/collection1/ against:[http://127.0.0.1:58230/zc_/collection1/, http://127.0.0.1:55587/zc_/collection1/] result:true
[junit4:junit4] 2> 691855 T2530 C900 P41544 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:55587/zc_/collection1/ against:[http://127.0.0.1:58230/zc_/collection1/, http://127.0.0.1:55587/zc_/collection1/] result:true
[junit4:junit4] 2> 691855 T2530 C900 P41544 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:36981/zc_/collection1/ against:[http://127.0.0.1:58230/zc_/collection1/, http://127.0.0.1:55587/zc_/collection1/] result:false
[junit4:junit4] 2> 691859 T2580 C899 P36981 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={distrib.from=http://127.0.0.1:41544/zc_/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:58230/zc_/collection1/&wt=javabin&version=2} {add=[3 (1439093692147171328)]} 0 1
[junit4:junit4] 2> 691859 T2530 C900 P41544 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={test.distrib.skip.servers=http://127.0.0.1:58230/zc_/collection1/&test.distrib.skip.servers=http://127.0.0.1:55587/zc_/collection1/&wt=javabin&version=2} {add=[3 (1439093692147171328)]} 0 5
[junit4:junit4] 2> 691861 T2511 C901 P59612 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 691882 T2511 C901 P59612 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@181f0f6; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@181f0f6; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 691883 T2511 C901 P59612 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 691885 T2511 C901 P59612 oass.SolrIndexSearcher.<init> Opening Searcher@100453a main
[junit4:junit4] 2> 691885 T2511 C901 P59612 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 691886 T2521 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@100453a main{StandardDirectoryReader(segments_2:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 691887 T2511 C901 P59612 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 26
[junit4:junit4] 2> 691889 T2546 C902 P58230 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:41544/zc_/collection1/, StdNode: http://127.0.0.1:58230/zc_/collection1/, StdNode: http://127.0.0.1:55587/zc_/collection1/, StdNode: http://127.0.0.1:36981/zc_/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 691891 T2531 C900 P41544 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 691891 T2549 C902 P58230 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 691891 T2563 C903 P55587 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 691891 T2582 C899 P36981 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 691952 T2563 C903 P55587 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d0f78a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d0f78a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 691953 T2563 C903 P55587 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 691952 T2582 C899 P36981 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@c37e55; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@c37e55; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 691952 T2531 C900 P41544 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@76b39d; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@76b39d; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 691955 T2531 C900 P41544 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 691952 T2549 C902 P58230 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@c3b1cf; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@c3b1cf; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 691956 T2563 C903 P55587 oass.SolrIndexSearcher.<init> Opening Searcher@15bad78 main
[junit4:junit4] 2> 691955 T2582 C899 P36981 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 691958 T2531 C900 P41544 oass.SolrIndexSearcher.<init> Opening Searcher@1ed73db main
[junit4:junit4] 2> 691957 T2563 C903 P55587 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 691957 T2549 C902 P58230 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 691959 T2531 C900 P41544 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 691959 T2572 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@15bad78 main{StandardDirectoryReader(segments_2:3:nrt _0(4.4):c3)}
[junit4:junit4] 2> 691961 T2582 C899 P36981 oass.SolrIndexSearcher.<init> Opening Searcher@198cb68 main
[junit4:junit4] 2> 691960 T2539 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ed73db main{StandardDirectoryReader(segments_2:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 691962 T2582 C899 P36981 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 691963 T2531 C900 P41544 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 72
[junit4:junit4] 2> 691962 T2563 C903 P55587 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 71
[junit4:junit4] 2> 691962 T2549 C902 P58230 oass.SolrIndexSearcher.<init> Opening Searcher@141fa3c main
[junit4:junit4] 2> 691964 T2591 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@198cb68 main{StandardDirectoryReader(segments_2:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 691965 T2549 C902 P58230 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 691966 T2582 C899 P36981 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 75
[junit4:junit4] 2> 691966 T2555 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@141fa3c main{StandardDirectoryReader(segments_2:3:nrt _0(4.4):c2)}
[junit4:junit4] 2> 691967 T2549 C902 P58230 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 76
[junit4:junit4] 2> 691968 T2546 C902 P58230 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 79
[junit4:junit4] 2> 691969 T2495 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 691970 T2495 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 691971 T2495 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 691974 T2533 C900 P41544 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 691977 T2547 C902 P58230 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=2 status=0 QTime=0
[junit4:junit4] 2> 691980 T2564 C903 P55587 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=3 status=0 QTime=1
[junit4:junit4] 2> 691983 T2581 C899 P36981 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> 691985 T2495 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 691995 T2566 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2
[junit4:junit4] 2> 691995 T2566 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 692001 T2532 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 692002 T2532 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:41544/zc_/collection1/
[junit4:junit4] 2> 692003 T2532 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:41544/zc_ START replicas=[http://127.0.0.1:58230/zc_/collection1/, http://127.0.0.1:55587/zc_/collection1/, http://127.0.0.1:36981/zc_/collection1/] nUpdates=100
[junit4:junit4] 2> 692005 T2548 C902 P58230 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 692005 T2583 C899 P36981 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 692005 T2565 C903 P55587 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 692006 T2532 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:41544/zc_ Received 3 versions from 127.0.0.1:58230/zc_/collection1/
[junit4:junit4] 2> 692006 T2532 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:41544/zc_ Our versions are newer. ourLowThreshold=1439093692090548224 otherHigh=1439093692116762624
[junit4:junit4] 2> 692007 T2532 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:41544/zc_ Received 5 versions from 127.0.0.1:36981/zc_/collection1/
[junit4:junit4] 2> 692007 T2532 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:41544/zc_ Our versions are newer. ourLowThreshold=1439093692090548224 otherHigh=1439093692133539840
[junit4:junit4] 2> 692007 T2532 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:41544/zc_ Received 4 versions from 127.0.0.1:55587/zc_/collection1/
[junit4:junit4] 2> 692008 T2532 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:41544/zc_ Our versions are newer. ourLowThreshold=1439093692090548224 otherHigh=1439093692133539840
[junit4:junit4] 2> 692008 T2532 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:41544/zc_ DONE. sync succeeded
[junit4:junit4] 2> 692008 T2532 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 692008 T2532 oasc.SyncStrategy.syncToMe http://127.0.0.1:41544/zc_/collection1/: try and ask http://127.0.0.1:58230/zc_/collection1/ to sync
[junit4:junit4] 2> 692009 T2532 oasc.SyncStrategy.syncToMe http://127.0.0.1:41544/zc_/collection1/: try and ask http://127.0.0.1:55587/zc_/collection1/ to sync
[junit4:junit4] 2> 692009 T2532 oasc.SyncStrategy.syncToMe http://127.0.0.1:41544/zc_/collection1/: try and ask http://127.0.0.1:36981/zc_/collection1/ to sync
[junit4:junit4] 2> 692010 T2549 C902 P58230 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58230/zc_ START replicas=[http://127.0.0.1:41544/zc_/collection1/] nUpdates=100
[junit4:junit4] 2> 692010 T2564 C903 P55587 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:55587/zc_ START replicas=[http://127.0.0.1:41544/zc_/collection1/] nUpdates=100
[junit4:junit4] 2> 692011 T2580 C899 P36981 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:36981/zc_ START replicas=[http://127.0.0.1:41544/zc_/collection1/] nUpdates=100
[junit4:junit4] 2> 692012 T2530 C900 P41544 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 692012 T2531 C900 P41544 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 692012 T2533 C900 P41544 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 692012 T2564 C903 P55587 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:55587/zc_ Received 5 versions from 127.0.0.1:41544/zc_/collection1/
[junit4:junit4] 2> 692015 T2549 C902 P58230 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:58230/zc_ Received 5 versions from 127.0.0.1:41544/zc_/collection1/
[junit4:junit4] 2> 692014 T2580 C899 P36981 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:36981/zc_ Received 5 versions from 127.0.0.1:41544/zc_/collection1/
[junit4:junit4] 2> 692016 T2549 C902 P58230 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:58230/zc_ Requesting updates from 127.0.0.1:41544/zc_/collection1/n=2 versions=[1439093692147171328, 1439093692133539840]
[junit4:junit4] 2> 692015 T2564 C903 P55587 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:55587/zc_ Requesting updates from 127.0.0.1:41544/zc_/collection1/n=1 versions=[1439093692147171328]
[junit4:junit4] 2> 692016 T2580 C899 P36981 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:36981/zc_ Our versions are newer. ourLowThreshold=1439093692090548224 otherHigh=1439093692133539840
[junit4:junit4] 2> 692018 T2580 C899 P36981 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:36981/zc_ DONE. sync succeeded
[junit4:junit4] 2> 692019 T2580 C899 P36981 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={sync=http://127.0.0.1:41544/zc_/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=8
[junit4:junit4] 2> 692020 T2530 C900 P41544 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={distrib=false&getUpdates=1439093692147171328,1439093692133539840&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 692020 T2531 C900 P41544 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={distrib=false&getUpdates=1439093692147171328&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 692020 T2532 oasc.SyncStrategy.syncToMe http://127.0.0.1:41544/zc_/collection1/: sync completed with http://127.0.0.1:36981/zc_/collection1/
[junit4:junit4] 2> 692023 T2564 C903 P55587 oasup.LogUpdateProcessor.finish [collection1] {add=[3 (1439093692147171328)]} 0 2
[junit4:junit4] 2> 692024 T2564 C903 P55587 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:55587/zc_ DONE. sync succeeded
[junit4:junit4] 2> 692024 T2564 C903 P55587 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={sync=http://127.0.0.1:41544/zc_/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=14
[junit4:junit4] 2> 692025 T2549 C902 P58230 oasup.LogUpdateProcessor.finish [collection1] {add=[2 (1439093692133539840), 3 (1439093692147171328)]} 0 4
[junit4:junit4] 2> 692025 T2532 oasc.SyncStrategy.syncToMe http://127.0.0.1:41544/zc_/collection1/: sync completed with http://127.0.0.1:55587/zc_/collection1/
[junit4:junit4] 2> 692026 T2549 C902 P58230 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58230/zc_ DONE. sync succeeded
[junit4:junit4] 2> 692027 T2549 C902 P58230 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={sync=http://127.0.0.1:41544/zc_/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=17
[junit4:junit4] 2> 692028 T2532 oasc.SyncStrategy.syncToMe http://127.0.0.1:41544/zc_/collection1/: sync completed with http://127.0.0.1:58230/zc_/collection1/
[junit4:junit4] 2> 692029 T2532 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={shard=shard1&action=REQUESTSYNCSHARD&core=collection1&collection=collection1&wt=javabin&version=2} status=0 QTime=28
[junit4:junit4] 2> 692029 T2566 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/collections params={shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2} status=0 QTime=36
[junit4:junit4] 2> 692030 T2495 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 692031 T2495 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 692032 T2495 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 692033 T2495 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 692036 T2513 C901 P59612 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 692037 T2513 C901 P59612 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 692039 T2513 C901 P59612 oass.SolrIndexSearcher.<init> Opening Searcher@10980eb main
[junit4:junit4] 2> 692040 T2513 C901 P59612 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 692041 T2521 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@10980eb main{StandardDirectoryReader(segments_2:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 692042 T2513 C901 P59612 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 692045 T2565 C903 P55587 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:41544/zc_/collection1/, StdNode: http://127.0.0.1:58230/zc_/collection1/, StdNode: http://127.0.0.1:55587/zc_/collection1/, StdNode: http://127.0.0.1:36981/zc_/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 692049 T2546 C902 P58230 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 692050 T2564 C903 P55587 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 692049 T2530 C900 P41544 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 692051 T2582 C899 P36981 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 692052 T2530 C900 P41544 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 692054 T2582 C899 P36981 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 692056 T2582 C899 P36981 oass.SolrIndexSearcher.<init> Opening Searcher@4349 main
[junit4:junit4] 2> 692057 T2582 C899 P36981 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 692055 T2530 C900 P41544 oass.SolrIndexSearcher.<init> Opening Searcher@e1ecc8 main
[junit4:junit4] 2> 692058 T2530 C900 P41544 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 692058 T2591 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4349 main{StandardDirectoryReader(segments_2:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 692060 T2539 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e1ecc8 main{StandardDirectoryReader(segments_2:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 692060 T2582 C899 P36981 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 692061 T2530 C900 P41544 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 12
[junit4:junit4] 2> 692122 T2546 C902 P58230 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@c3b1cf; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@c3b1cf; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 692123 T2546 C902 P58230 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 692123 T2564 C903 P55587 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d0f78a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1d0f78a; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 692124 T2564 C903 P55587 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 692124 T2546 C902 P58230 oass.SolrIndexSearcher.<init> Opening Searcher@118c418 main
[junit4:junit4] 2> 692125 T2546 C902 P58230 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 692125 T2564 C903 P55587 oass.SolrIndexSearcher.<init> Opening Searcher@1ae01f4 main
[junit4:junit4] 2> 692125 T2555 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@118c418 main{StandardDirectoryReader(segments_3:5:nrt _0(4.4):c2 _1(4.4):c2)}
[junit4:junit4] 2> 692125 T2564 C903 P55587 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 692126 T2546 C902 P58230 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 77
[junit4:junit4] 2> 692126 T2572 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ae01f4 main{StandardDirectoryReader(segments_3:5:nrt _0(4.4):c3 _1(4.4):c1)}
[junit4:junit4] 2> 692126 T2564 C903 P55587 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 76
[junit4:junit4] 2> 692127 T2565 C903 P55587 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 82
[junit4:junit4] 2> 692127 T2495 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 692130 T2531 C900 P41544 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 692132 T2547 C902 P58230 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 692134 T2566 C903 P55587 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 692136 T2581 C899 P36981 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 694137 T2495 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> check const of shard1
[junit4:junit4] 2> client0
[junit4:junit4] 2> PROPS:2:{"shard":"shard1","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:41544_zc_","base_url":"http://127.0.0.1:41544/zc_","leader":"true"}
[junit4:junit4] 2> 694140 T2530 C900 P41544 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:4
[junit4:junit4] 2>
[junit4:junit4] 2> client1
[junit4:junit4] 2> PROPS:3:{"shard":"shard1","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:58230_zc_","base_url":"http://127.0.0.1:58230/zc_"}
[junit4:junit4] 2> 694142 T2547 C902 P58230 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:4
[junit4:junit4] 2>
[junit4:junit4] 2> client2
[junit4:junit4] 2> PROPS:4:{"shard":"shard1","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:55587_zc_","base_url":"http://127.0.0.1:55587/zc_"}
[junit4:junit4] 2> 694145 T2565 C903 P55587 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:4
[junit4:junit4] 2>
[junit4:junit4] 2> client3
[junit4:junit4] 2> PROPS:5:{"shard":"shard1","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:36981_zc_","base_url":"http://127.0.0.1:36981/zc_"}
[junit4:junit4] 2> 694149 T2582 C899 P36981 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:4
[junit4:junit4] 2>
[junit4:junit4] 2> 694152 T2563 C903 P55587 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/select params={q=*:*&wt=javabin&version=2} hits=4 status=0 QTime=0
[junit4:junit4] 2> 694157 T2511 C901 P59612 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={wt=javabin&version=2} {add=[4 (1439093694558896128)]} 0 2
[junit4:junit4] 2> 694162 T2531 C900 P41544 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:58230/zc_/collection1/]
[junit4:junit4] 2> 694162 T2531 C900 P41544 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:58230/zc_/collection1/ against:[http://127.0.0.1:58230/zc_/collection1/] result:true
[junit4:junit4] 2> 694163 T2531 C900 P41544 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:55587/zc_/collection1/ against:[http://127.0.0.1:58230/zc_/collection1/] result:false
[junit4:junit4] 2> 694163 T2531 C900 P41544 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:36981/zc_/collection1/ against:[http://127.0.0.1:58230/zc_/collection1/] result:false
[junit4:junit4] 2> 694170 T2566 C903 P55587 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={distrib.from=http://127.0.0.1:41544/zc_/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:58230/zc_/collection1/&wt=javabin&version=2} {add=[4 (1439093694567284736)]} 0 2
[junit4:junit4] 2> 694170 T2581 C899 P36981 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={distrib.from=http://127.0.0.1:41544/zc_/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:58230/zc_/collection1/&wt=javabin&version=2} {add=[4 (1439093694567284736)]} 0 2
[junit4:junit4] 2> 694171 T2531 C900 P41544 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={distrib.from=http://127.0.0.1:58230/zc_/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:58230/zc_/collection1/&wt=javabin&version=2} {add=[4 (1439093694567284736)]} 0 9
[junit4:junit4] 2> 694171 T2549 C902 P58230 oasup.LogUpdateProcessor.finish [collection1] webapp=/zc_ path=/update params={test.distrib.skip.servers=http://127.0.0.1:58230/zc_/collection1/&wt=javabin&version=2} {add=[4]} 0 11
[junit4:junit4] 2> 694172 T2495 oasc.ChaosMonkey.monkeyLog monkey: kill shard! 41544
[junit4:junit4] 2> 694194 T2495 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=12388664
[junit4:junit4] 2> 694955 T2518 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 694956 T2518 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:41544_zc_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41544/zc_"}
[junit4:junit4] 2> 694962 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 694962 T2587 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 694962 T2537 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 694963 T2570 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 694962 T2524 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 694962 T2553 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeDataChanged path:/clusterstate.json, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 696196 T2495 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 696196 T2495 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 696199 T2495 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@f7f97c
[junit4:junit4] 2> 696204 T2495 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=6,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=1,adds=1,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=5,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 696205 T2495 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 696206 T2495 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 696206 T2495 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> C900_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=down, core=collection1, collection=collection1, node_name=127.0.0.1:41544_zc_, base_url=http://127.0.0.1:41544/zc_, leader=true}
[junit4:junit4] 2> 696222 T2495 C900 P41544 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@76b39d; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@76b39d; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@76b39d; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 696223 T2495 C900 P41544 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 696225 T2495 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 696225 T2495 oasc.CachingDirectoryFactory.close Closing NRTCachingDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 696225 T2495 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1;done=false>>]
[junit4:junit4] 2> 696226 T2495 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1
[junit4:junit4] 2> 696226 T2495 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1/index [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1/index;done=false>>]
[junit4:junit4] 2> 696226 T2495 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372426671468/jetty1/index
[junit4:junit4] 2> 696229 T2524 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 5)
[junit4:junit4] 2> 696229 T2517 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 696229 T2587 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 696229 T2570 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 696229 T2553 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 696229 T2517 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 696230 T2495 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/zc_,null}
[junit4:junit4] 2> 696229 T2570 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 696229 T2587 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 4)
[junit4:junit4] 2> 696230 T2524 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 696232 T2553 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4] 2> 696232 T2553 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4] 2> 696232 T2553 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 696233 T2553 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58230/zc_/collection1/
[junit4:junit4] 2> 696233 T2553 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58230/zc_ START replicas=[http://127.0.0.1:41544/zc_/collection1/, http://127.0.0.1:55587/zc_/collection1/, http://127.0.0.1:36981/zc_/collection1/] nUpdates=100
[junit4:junit4] 2> 696234 T2553 oasu.PeerSync.handleResponse WARN PeerSync: core=collection1 url=http://127.0.0.1:58230/zc_ couldn't connect to http://127.0.0.1:41544/zc_/collection1/, counting as success
[junit4:junit4] 2> 696235 T2565 C903 P55587 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 696235 T2583 C899 P36981 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 696235 T2553 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:58230/zc_ Received 6 versions from 127.0.0.1:55587/zc_/collection1/
[junit4:junit4] 2> 696236 T2553 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:58230/zc_ Requesting updates from 127.0.0.1:55587/zc_/collection1/n=1 versions=[1439093694567284736]
[junit4:junit4] 2> 696236 T2553 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:58230/zc_ Received 6 versions from 127.0.0.1:36981/zc_/collection1/
[junit4:junit4] 2> 696236 T2553 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:58230/zc_ Our versions are newer. ourLowThreshold=1439093692090548224 otherHigh=1439093692147171328
[junit4:junit4] 2> 696238 T2564 C903 P55587 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={distrib=false&getUpdates=1439093694567284736&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 696240 T2553 oasup.LogUpdateProcessor.finish [collection1] {add=[4 (1439093694567284736)]} 0 2
[junit4:junit4] 2> 696240 T2553 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58230/zc_ DONE. sync succeeded
[junit4:junit4] 2> 696240 T2553 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 696241 T2553 oasc.SyncStrategy.syncToMe http://127.0.0.1:58230/zc_/collection1/: try and ask http://127.0.0.1:41544/zc_/collection1/ to sync
[junit4:junit4] 2> 696241 T2553 oasc.SyncStrategy.syncToMe http://127.0.0.1:58230/zc_/collection1/: try and ask http://127.0.0.1:55587/zc_/collection1/ to sync
[junit4:junit4] 2> 696241 T2553 oasc.SyncStrategy.syncToMe http://127.0.0.1:58230/zc_/collection1/: try and ask http://127.0.0.1:36981/zc_/collection1/ to sync
[junit4:junit4] 2> 696242 T2553 oasc.SolrException.log ERROR Sync request error: org.apache.solr.client.solrj.SolrServerException: Server refused connection at: http://127.0.0.1:41544/zc_/collection1
[junit4:junit4] 2> 696242 T2553 oasc.SyncStrategy.syncToMe http://127.0.0.1:58230/zc_/collection1/: Sync failed - asking replica (http://127.0.0.1:41544/zc_/collection1/) to recover.
[junit4:junit4] 2> 696242 T2622 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 696243 T2563 C903 P55587 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:55587/zc_ START replicas=[http://127.0.0.1:58230/zc_/collection1/] nUpdates=100
[junit4:junit4] 2> 696243 T2582 C899 P36981 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:36981/zc_ START replicas=[http://127.0.0.1:58230/zc_/collection1/] nUpdates=100
[junit4:junit4] 2> 696245 T2549 C902 P58230 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 696245 T2582 C899 P36981 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:36981/zc_ Received 6 versions from 127.0.0.1:58230/zc_/collection1/
[junit4:junit4] 2> 696245 T2546 C902 P58230 oasc.SolrCore.execute [collection1] webapp=/zc_ path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 696245 T2582 C899 P36981 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:36981/zc_ Our versions are newer. ourLowThreshold=1439093692104179712 otherHigh=1439093692147171328
[junit4:junit4] 2> 696246 T2582 C899 P36981 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:36981/zc_ DONE. sync succeeded
[junit4:junit4] 2> 696246 T2622 oasc.SolrException.log ERROR http://127.0.0.1:58230/zc_/collection1/: Could not tell a replica to recover:org.apache.solr.client.solrj.SolrServerException: Server refused connection at: http://127.0.0.1:41544/zc_
[junit4:junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:428)
[junit4:junit4] 2> at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] 2> at org.apache.solr.cloud.SyncStrategy$1.run(SyncStrategy.java:298)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] 2> at java.la
[...truncated too long message...]
t4] 1> "state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "node_name":"127.0.0.1:59612_zc_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:59612/zc_",
[junit4:junit4] 1> "leader":"true"}}}},
[junit4:junit4] 1> "router":"compositeId"}}
[junit4:junit4] 1> /solr/aliases.json (0)
[junit4:junit4] 1> /solr/live_nodes (4)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:55587_zc_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:59612_zc_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:41544_zc_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:36981_zc_ (0)
[junit4:junit4] 1> /solr/overseer (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1> /solr/overseer/queue (0)
[junit4:junit4] 1> /solr/overseer/queue-work (0)
[junit4:junit4] 1> /solr/overseer/collection-queue-work (0)
[junit4:junit4] 1> /solr/collections (2)
[junit4:junit4] 1> /solr/collections/collection1 (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/collection1/shards (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election (3)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89943354341457934-2-n_0000000004 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89943354341457930-4-n_0000000002 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89943354341457932-5-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections/collection1/leaders (1)
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:55587_zc_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:55587/zc_"}
[junit4:junit4] 1> /solr/collections/control_collection (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/control_collection/shards (0)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election/89943354341457923-1-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/control_collection/leaders (1)
[junit4:junit4] 1> /solr/collections/control_collection/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:59612_zc_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:59612/zc_"}
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (4)
[junit4:junit4] 1> /solr/overseer_elect/election/89943354341457934-127.0.0.1:41544_zc_-n_0000000005 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89943354341457932-127.0.0.1:36981_zc_-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89943354341457930-127.0.0.1:55587_zc_-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89943354341457923-127.0.0.1:59612_zc_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89943354341457923-127.0.0.1:59612_zc_-n_0000000000"}
[junit4:junit4] 1> /zookeeper (1)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=SyncSliceTest -Dtests.method=testDistribSearch -Dtests.seed=31DBD35871971BC9 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ru -Dtests.timezone=Europe/Volgograd -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] FAILURE 99.5s J0 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:41544/zc_/collection1lastClient and got 247 from http://127.0.0.1:55587/zc_/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([31DBD35871971BC9:B03D5D4006C87BF5]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
[junit4:junit4] > at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2> 769765 T2495 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 99553 T2494 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> 769826 T2570 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 769827 T2570 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 2)
[junit4:junit4] 2> 769827 T2570 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {range_facet_l=Pulsing41(freqCutoff=15 minBlockSize=72 maxBlockSize=179), text=PostingsFormat(name=SimpleText), _version_=Pulsing41(freqCutoff=15 minBlockSize=72 maxBlockSize=179), rnd_b=PostingsFormat(name=MockSep), intDefault=Pulsing41(freqCutoff=15 minBlockSize=72 maxBlockSize=179), timestamp=Pulsing41(freqCutoff=15 minBlockSize=72 maxBlockSize=179), id=PostingsFormat(name=MockSep), a_t=Pulsing41(freqCutoff=15 minBlockSize=72 maxBlockSize=179), range_facet_sl=PostingsFormat(name=SimpleText), range_facet_si=MockFixedIntBlock(blockSize=308), other_tl1=Pulsing41(freqCutoff=15 minBlockSize=72 maxBlockSize=179), multiDefault=MockFixedIntBlock(blockSize=308), a_si=MockFixedIntBlock(blockSize=308)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=crazy): {}, locale=ru, timezone=Europe/Volgograd
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic i386/Oracle Corporation 1.7.0_25 (32-bit)/cpus=8,threads=2,free=99834608,total=420478976
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestFastWriter, MinimalSchemaTest, TestSolrQueryParser, TestCopyFieldCollectionResource, TestPseudoReturnFields, SimpleFacetsTest, AnalysisAfterCoreReloadTest, TestWriterPerf, ShardRoutingTest, TestSolrCoreProperties, SolrCoreTest, SpatialFilterTest, UnloadDistributedZkTest, SolrIndexSplitterTest, MBeansHandlerTest, TestRealTimeGet, TestConfig, DistributedQueryElevationComponentTest, TestShardHandlerFactory, TestDefaultSearchFieldResource, TestSolrQueryParserResource, OverseerCollectionProcessorTest, ReturnFieldsTest, TestBadConfig, TestIBSimilarityFactory, FieldMutatingUpdateProcessorTest, TestStressRecovery, SchemaVersionSpecificBehaviorTest, TestPluginEnable, BadComponentTest, DistributedSpellCheckComponentTest, TestReversedWildcardFilterFactory, TestDynamicFieldCollectionResource, WordBreakSolrSpellCheckerTest, TestAddFieldRealTimeGet, TestRandomDVFaceting, TestSolrDeletionPolicy2, CircularListTest, SynonymTokenizerTest, ResponseLogComponentTest, RAMDirectoryFactoryTest, TestPhraseSuggestions, LeaderElectionTest, RecoveryZkTest, TestSearchPerf, IndexSchemaTest, TestLRUCache, TestRemoteStreaming, TestDocumentBuilder, TestCharFilters, TestManagedSchemaFieldResource, SystemInfoHandlerTest, TestSchemaNameResource, PreAnalyzedUpdateProcessorTest, TestFastLRUCache, SoftAutoCommitTest, SOLR749Test, BinaryUpdateRequestHandlerTest, UUIDFieldTest, DirectSolrConnectionTest, SuggesterFSTTest, TestLFUCache, TestSolrQueryParserDefaultOperatorResource, TestSurroundQueryParser, SearchHandlerTest, TestSolrIndexConfig, LukeRequestHandlerTest, CacheHeaderTest, TestLMDirichletSimilarityFactory, SliceStateTest, TestJoin, BasicFunctionalityTest, OverseerTest, BasicDistributedZkTest, SyncSliceTest]
[junit4:junit4] Completed on J0 in 99.84s, 1 test, 1 failure <<< FAILURES!
[...truncated 461 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:392: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:372: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1248: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:892: There were test failures: 299 suites, 1290 tests, 1 failure, 12 ignored (6 assumptions)
Total time: 41 minutes 46 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_25 -server -XX:+UseG1GC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure