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 04:40:20 UTC
[JENKINS] Lucene-Solr-trunk-Linux (64bit/jdk1.7.0_25) - Build #
6344 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/6344/
Java: 64bit/jdk1.7.0_25 -XX:+UseCompressedOops -XX:+UseSerialGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:46289/collection1lastClient and got 253 from http://127.0.0.1:53246/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:46289/collection1lastClient and got 253 from http://127.0.0.1:53246/collection1
at __randomizedtesting.SeedInfo.seed([EFFBC37F60AB5480:6E1D4D6717F434BC]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1045)
at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:237)
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 9626 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 360175 T1350 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 360181 T1350 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1372386336906
[junit4:junit4] 2> 360181 T1350 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 360182 T1351 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 360282 T1350 oasc.ZkTestServer.run start zk server on port:42345
[junit4:junit4] 2> 360283 T1350 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 360348 T1357 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@67485737 name:ZooKeeperConnection Watcher:127.0.0.1:42345 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 360348 T1350 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 360348 T1350 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 360353 T1350 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 360354 T1359 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3b3f24bd name:ZooKeeperConnection Watcher:127.0.0.1:42345/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 360354 T1350 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 360354 T1350 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 360357 T1350 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 360360 T1350 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 360361 T1350 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 360364 T1350 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 360364 T1350 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 360369 T1350 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 360369 T1350 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 360372 T1350 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 360372 T1350 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 360375 T1350 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 360376 T1350 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 360379 T1350 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 360380 T1350 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 360383 T1350 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 360383 T1350 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 360386 T1350 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 360387 T1350 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 360390 T1350 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 360391 T1350 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 360394 T1350 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 360395 T1350 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 360511 T1350 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 360529 T1350 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55834
[junit4:junit4] 2> 360530 T1350 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 360530 T1350 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 360530 T1350 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372386337124
[junit4:junit4] 2> 360531 T1350 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372386337124/solr.xml
[junit4:junit4] 2> 360531 T1350 oasc.CoreContainer.<init> New CoreContainer 1930102100
[junit4:junit4] 2> 360532 T1350 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372386337124/'
[junit4:junit4] 2> 360532 T1350 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372386337124/'
[junit4:junit4] 2> 360603 T1350 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 360603 T1350 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 360603 T1350 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 360604 T1350 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 360604 T1350 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 360605 T1350 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 360605 T1350 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 360605 T1350 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 360606 T1350 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 360606 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 360611 T1350 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 360612 T1350 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42345/solr
[junit4:junit4] 2> 360612 T1350 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 360613 T1350 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 360615 T1370 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2918b76c name:ZooKeeperConnection Watcher:127.0.0.1:42345 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 360615 T1350 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 360617 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 360622 T1350 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 360622 T1372 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@32cc40df name:ZooKeeperConnection Watcher:127.0.0.1:42345/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 360623 T1350 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 360626 T1350 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 360628 T1350 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 360631 T1350 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 360632 T1350 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55834_
[junit4:junit4] 2> 360633 T1350 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55834_
[junit4:junit4] 2> 360635 T1350 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 360639 T1350 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 360642 T1350 oasc.Overseer.start Overseer (id=89940710975668227-127.0.0.1:55834_-n_0000000000) starting
[junit4:junit4] 2> 360644 T1350 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 360647 T1374 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 360648 T1350 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 360650 T1350 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 360652 T1350 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 360654 T1373 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 360657 T1375 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 360657 T1375 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 360658 T1375 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 362157 T1373 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 362157 T1373 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[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:55834_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55834"}
[junit4:junit4] 2> 362157 T1373 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 362158 T1373 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 362162 T1372 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> 362659 T1375 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 362659 T1375 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372386337124/collection1
[junit4:junit4] 2> 362659 T1375 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 362660 T1375 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 362660 T1375 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 362661 T1375 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372386337124/collection1/'
[junit4:junit4] 2> 362662 T1375 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372386337124/collection1/lib/README' to classloader
[junit4:junit4] 2> 362662 T1375 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372386337124/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 362684 T1375 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 362718 T1375 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 362720 T1375 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 362725 T1375 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 363055 T1375 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 363060 T1375 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 363062 T1375 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 363075 T1375 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 363078 T1375 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 363081 T1375 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 363082 T1375 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 363083 T1375 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 363083 T1375 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 363084 T1375 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 363084 T1375 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 363084 T1375 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 363084 T1375 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372386337124/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372386336906/control/data/
[junit4:junit4] 2> 363084 T1375 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@63d625cf
[junit4:junit4] 2> 363085 T1375 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1372386336906/control/data
[junit4:junit4] 2> 363085 T1375 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372386336906/control/data/index/
[junit4:junit4] 2> 363085 T1375 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372386336906/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 363086 T1375 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1372386336906/control/data/index
[junit4:junit4] 2> 363087 T1375 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3080dfc0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a78eb4f),segFN=segments_1,generation=1}
[junit4:junit4] 2> 363087 T1375 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 363089 T1375 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 363089 T1375 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 363089 T1375 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 363090 T1375 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 363090 T1375 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 363090 T1375 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 363090 T1375 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 363091 T1375 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 363091 T1375 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 363093 T1375 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 363095 T1375 oass.SolrIndexSearcher.<init> Opening Searcher@49d523bd main
[junit4:junit4] 2> 363096 T1375 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 363096 T1375 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 363099 T1376 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@49d523bd main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 363101 T1375 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 363101 T1375 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55834 collection:control_collection shard:shard1
[junit4:junit4] 2> 363102 T1375 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 363109 T1375 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4:junit4] 2> 363111 T1375 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 363112 T1375 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 363112 T1375 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:55834/collection1/
[junit4:junit4] 2> 363112 T1375 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 363112 T1375 oasc.SyncStrategy.syncToMe http://127.0.0.1:55834/collection1/ has no replicas
[junit4:junit4] 2> 363112 T1375 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:55834/collection1/ shard1
[junit4:junit4] 2> 363113 T1375 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 363666 T1373 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 363770 T1372 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> 363820 T1375 oasc.ZkController.register We are http://127.0.0.1:55834/collection1/ and leader is http://127.0.0.1:55834/collection1/
[junit4:junit4] 2> 363820 T1375 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55834
[junit4:junit4] 2> 363820 T1375 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 363820 T1375 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 363820 T1375 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 363822 T1375 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 363823 T1350 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 363824 T1350 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 363824 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 363827 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 363828 T1350 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 363829 T1379 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@58160683 name:ZooKeeperConnection Watcher:127.0.0.1:42345/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 363829 T1350 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 363831 T1350 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 363832 T1350 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 363918 T1350 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 363921 T1350 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:46289
[junit4:junit4] 2> 363921 T1350 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 363922 T1350 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 363922 T1350 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372386340558
[junit4:junit4] 2> 363922 T1350 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372386340558/solr.xml
[junit4:junit4] 2> 363923 T1350 oasc.CoreContainer.<init> New CoreContainer 375753542
[junit4:junit4] 2> 363923 T1350 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372386340558/'
[junit4:junit4] 2> 363924 T1350 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372386340558/'
[junit4:junit4] 2> 363974 T1350 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 363975 T1350 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 363975 T1350 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 363975 T1350 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 363976 T1350 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 363976 T1350 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 363976 T1350 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 363976 T1350 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 363977 T1350 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 363977 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 363980 T1350 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 363980 T1350 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42345/solr
[junit4:junit4] 2> 363980 T1350 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 363981 T1350 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 363989 T1390 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1da9150e name:ZooKeeperConnection Watcher:127.0.0.1:42345 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 363989 T1350 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 363990 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 363994 T1350 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 363996 T1392 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@26ae163d name:ZooKeeperConnection Watcher:127.0.0.1:42345/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 363996 T1350 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 364000 T1350 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 365002 T1350 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46289_
[junit4:junit4] 2> 365004 T1350 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46289_
[junit4:junit4] 2> 365007 T1379 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 365007 T1392 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 365008 T1372 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 365008 T1372 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> 365014 T1393 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 365014 T1393 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 365015 T1393 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 365275 T1373 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 365275 T1373 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[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:55834_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55834"}
[junit4:junit4] 2> 365279 T1373 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[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:46289_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46289"}
[junit4:junit4] 2> 365279 T1373 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 365279 T1373 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 365284 T1372 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> 365284 T1379 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> 365284 T1392 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> 366016 T1393 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 366016 T1393 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372386340558/collection1
[junit4:junit4] 2> 366016 T1393 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 366017 T1393 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 366017 T1393 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 366018 T1393 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372386340558/collection1/'
[junit4:junit4] 2> 366019 T1393 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372386340558/collection1/lib/README' to classloader
[junit4:junit4] 2> 366019 T1393 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372386340558/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 366046 T1393 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 366082 T1393 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 366083 T1393 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 366087 T1393 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 366435 T1393 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 366443 T1393 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 366445 T1393 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 366459 T1393 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 366463 T1393 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 366465 T1393 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 366466 T1393 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 366467 T1393 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 366467 T1393 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 366468 T1393 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 366468 T1393 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 366468 T1393 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 366469 T1393 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372386340558/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty1/
[junit4:junit4] 2> 366469 T1393 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@63d625cf
[junit4:junit4] 2> 366470 T1393 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty1
[junit4:junit4] 2> 366470 T1393 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty1/index/
[junit4:junit4] 2> 366470 T1393 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 366471 T1393 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty1/index
[junit4:junit4] 2> 366472 T1393 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10a9c47e lockFactory=org.apache.lucene.store.NativeFSLockFactory@72957363),segFN=segments_1,generation=1}
[junit4:junit4] 2> 366473 T1393 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 366475 T1393 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 366475 T1393 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 366476 T1393 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 366477 T1393 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 366477 T1393 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 366478 T1393 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 366478 T1393 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 366479 T1393 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 366479 T1393 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 366482 T1393 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 366486 T1393 oass.SolrIndexSearcher.<init> Opening Searcher@4fbd8981 main
[junit4:junit4] 2> 366487 T1393 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 366487 T1393 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 366492 T1394 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4fbd8981 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 366495 T1393 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 366495 T1393 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46289 collection:collection1 shard:shard1
[junit4:junit4] 2> 366495 T1393 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 366501 T1393 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4:junit4] 2> 366503 T1393 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 366503 T1393 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 366503 T1393 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:46289/collection1/
[junit4:junit4] 2> 366504 T1393 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 366504 T1393 oasc.SyncStrategy.syncToMe http://127.0.0.1:46289/collection1/ has no replicas
[junit4:junit4] 2> 366504 T1393 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:46289/collection1/ shard1
[junit4:junit4] 2> 366504 T1393 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 366790 T1373 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 366798 T1392 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> 366798 T1372 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> 366798 T1379 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> 366809 T1393 oasc.ZkController.register We are http://127.0.0.1:46289/collection1/ and leader is http://127.0.0.1:46289/collection1/
[junit4:junit4] 2> 366810 T1393 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46289
[junit4:junit4] 2> 366810 T1393 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 366810 T1393 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 366810 T1393 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 366812 T1393 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 366813 T1350 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 366813 T1350 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 366814 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 366917 T1350 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 366919 T1350 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40211
[junit4:junit4] 2> 366920 T1350 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 366920 T1350 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 366921 T1350 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372386343543
[junit4:junit4] 2> 366921 T1350 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372386343543/solr.xml
[junit4:junit4] 2> 366922 T1350 oasc.CoreContainer.<init> New CoreContainer 206223541
[junit4:junit4] 2> 366922 T1350 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372386343543/'
[junit4:junit4] 2> 366922 T1350 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372386343543/'
[junit4:junit4] 2> 366977 T1350 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 366977 T1350 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 366978 T1350 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 366978 T1350 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 366978 T1350 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 366978 T1350 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 366979 T1350 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 366979 T1350 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 366979 T1350 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 366980 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 366983 T1350 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 366984 T1350 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42345/solr
[junit4:junit4] 2> 366984 T1350 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 366985 T1350 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 366987 T1406 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@38047f04 name:ZooKeeperConnection Watcher:127.0.0.1:42345 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 366987 T1350 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 366988 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 366992 T1350 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 366993 T1408 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6e6432c1 name:ZooKeeperConnection Watcher:127.0.0.1:42345/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 366993 T1350 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 366996 T1350 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 367999 T1350 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40211_
[junit4:junit4] 2> 368000 T1350 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40211_
[junit4:junit4] 2> 368004 T1372 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 368004 T1408 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 368004 T1392 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 368004 T1372 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> 368005 T1392 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> 368005 T1379 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 368005 T1379 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> 368010 T1409 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 368011 T1409 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 368012 T1409 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 368303 T1373 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 368304 T1373 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[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:46289_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46289"}
[junit4:junit4] 2> 368307 T1373 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node2",
[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:40211_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40211"}
[junit4:junit4] 2> 368307 T1373 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 368307 T1373 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 368310 T1408 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> 368310 T1372 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> 368310 T1379 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> 368310 T1392 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> 369012 T1409 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 369012 T1409 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372386343543/collection1
[junit4:junit4] 2> 369012 T1409 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 369013 T1409 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 369013 T1409 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 369014 T1409 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372386343543/collection1/'
[junit4:junit4] 2> 369015 T1409 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372386343543/collection1/lib/README' to classloader
[junit4:junit4] 2> 369015 T1409 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372386343543/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 369046 T1409 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 369072 T1409 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 369074 T1409 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 369077 T1409 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 369413 T1409 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 369418 T1409 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 369421 T1409 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 369433 T1409 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 369436 T1409 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 369438 T1409 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 369439 T1409 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 369440 T1409 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 369440 T1409 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 369441 T1409 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 369441 T1409 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 369441 T1409 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 369442 T1409 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372386343543/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty2/
[junit4:junit4] 2> 369442 T1409 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@63d625cf
[junit4:junit4] 2> 369443 T1409 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty2
[junit4:junit4] 2> 369443 T1409 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty2/index/
[junit4:junit4] 2> 369443 T1409 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 369443 T1409 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty2/index
[junit4:junit4] 2> 369445 T1409 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6db20cfc lockFactory=org.apache.lucene.store.NativeFSLockFactory@37ad4409),segFN=segments_1,generation=1}
[junit4:junit4] 2> 369445 T1409 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 369447 T1409 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 369448 T1409 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 369448 T1409 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 369449 T1409 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 369450 T1409 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 369450 T1409 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 369450 T1409 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 369451 T1409 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 369451 T1409 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 369454 T1409 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 369464 T1409 oass.SolrIndexSearcher.<init> Opening Searcher@2a118704 main
[junit4:junit4] 2> 369465 T1409 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 369465 T1409 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 369469 T1410 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2a118704 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 369471 T1409 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 369471 T1409 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40211 collection:collection1 shard:shard1
[junit4:junit4] 2> 369474 T1409 oasc.ZkController.register We are http://127.0.0.1:40211/collection1/ and leader is http://127.0.0.1:46289/collection1/
[junit4:junit4] 2> 369474 T1409 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40211
[junit4:junit4] 2> 369474 T1409 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 369474 T1409 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1407 name=collection1 org.apache.solr.core.SolrCore@58e34bb3 url=http://127.0.0.1:40211/collection1 node=127.0.0.1:40211_ C1407_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:40211_, base_url=http://127.0.0.1:40211}
[junit4:junit4] 2> 369474 T1411 C1407 P40211 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 369475 T1409 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 369475 T1411 C1407 P40211 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 369475 T1411 C1407 P40211 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 369476 T1411 C1407 P40211 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 369476 T1350 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 369476 T1350 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 369477 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 369483 T1411 C1407 P40211 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 369486 T1386 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node2, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 369588 T1350 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 369591 T1350 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53246
[junit4:junit4] 2> 369592 T1350 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 369592 T1350 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 369592 T1350 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372386346206
[junit4:junit4] 2> 369593 T1350 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372386346206/solr.xml
[junit4:junit4] 2> 369593 T1350 oasc.CoreContainer.<init> New CoreContainer 209802602
[junit4:junit4] 2> 369594 T1350 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372386346206/'
[junit4:junit4] 2> 369594 T1350 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372386346206/'
[junit4:junit4] 2> 369663 T1350 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 369664 T1350 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 369664 T1350 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 369665 T1350 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 369665 T1350 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 369666 T1350 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 369666 T1350 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 369666 T1350 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 369667 T1350 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 369667 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 369672 T1350 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 369673 T1350 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42345/solr
[junit4:junit4] 2> 369673 T1350 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 369683 T1350 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 369685 T1423 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2d6eed3f name:ZooKeeperConnection Watcher:127.0.0.1:42345 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 369685 T1350 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 369687 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 369692 T1350 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 369696 T1425 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10fc121a name:ZooKeeperConnection Watcher:127.0.0.1:42345/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 369696 T1350 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 369700 T1350 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 369815 T1373 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 369816 T1373 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node2",
[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:40211_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40211"}
[junit4:junit4] 2> 369821 T1425 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> 369821 T1372 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> 369822 T1392 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> 369821 T1379 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> 369821 T1408 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> 370487 T1386 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node2, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 370487 T1386 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node2&state=recovering&nodeName=127.0.0.1:40211_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 370703 T1350 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53246_
[junit4:junit4] 2> 370705 T1350 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53246_
[junit4:junit4] 2> 370707 T1425 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> 370707 T1408 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> 370707 T1379 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 370707 T1392 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 370708 T1379 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> 370708 T1372 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 370708 T1392 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> 370708 T1372 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> 370710 T1425 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 370710 T1408 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 370714 T1426 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 370715 T1426 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 370716 T1426 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 371325 T1373 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 371326 T1373 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node3",
[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:53246_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53246"}
[junit4:junit4] 2> 371326 T1373 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 371327 T1373 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 371330 T1425 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> 371330 T1408 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> 371330 T1372 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> 371330 T1379 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> 371331 T1392 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> 371716 T1426 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 371716 T1426 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372386346206/collection1
[junit4:junit4] 2> 371717 T1426 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 371717 T1426 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 371717 T1426 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 371719 T1426 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372386346206/collection1/'
[junit4:junit4] 2> 371719 T1426 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372386346206/collection1/lib/README' to classloader
[junit4:junit4] 2> 371720 T1426 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372386346206/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 371756 T1426 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 371809 T1426 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 371810 T1426 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 371815 T1426 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 372290 T1426 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 372299 T1426 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 372303 T1426 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 372323 T1426 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 372328 T1426 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 372332 T1426 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 372334 T1426 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 372334 T1426 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 372334 T1426 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 372336 T1426 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 372336 T1426 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 372337 T1426 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 372337 T1426 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372386346206/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty3/
[junit4:junit4] 2> 372337 T1426 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@63d625cf
[junit4:junit4] 2> 372338 T1426 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty3
[junit4:junit4] 2> 372338 T1426 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty3/index/
[junit4:junit4] 2> 372339 T1426 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 372339 T1426 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty3/index
[junit4:junit4] 2> 372341 T1426 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@11cd34fe lockFactory=org.apache.lucene.store.NativeFSLockFactory@25920678),segFN=segments_1,generation=1}
[junit4:junit4] 2> 372341 T1426 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 372344 T1426 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 372344 T1426 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 372345 T1426 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 372345 T1426 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 372346 T1426 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 372346 T1426 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 372347 T1426 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 372347 T1426 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 372348 T1426 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 372351 T1426 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 372355 T1426 oass.SolrIndexSearcher.<init> Opening Searcher@31866e81 main
[junit4:junit4] 2> 372355 T1426 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 372356 T1426 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 372361 T1427 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@31866e81 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 372364 T1426 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 372364 T1426 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53246 collection:collection1 shard:shard1
[junit4:junit4] 2> 372368 T1426 oasc.ZkController.register We are http://127.0.0.1:53246/collection1/ and leader is http://127.0.0.1:46289/collection1/
[junit4:junit4] 2> 372368 T1426 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53246
[junit4:junit4] 2> 372369 T1426 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 372369 T1426 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1408 name=collection1 org.apache.solr.core.SolrCore@58959f4f url=http://127.0.0.1:53246/collection1 node=127.0.0.1:53246_ C1408_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:53246_, base_url=http://127.0.0.1:53246}
[junit4:junit4] 2> 372369 T1428 C1408 P53246 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 372370 T1428 C1408 P53246 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 372370 T1426 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 372370 T1428 C1408 P53246 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 372371 T1428 C1408 P53246 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 372372 T1350 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 372372 T1350 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 372373 T1428 C1408 P53246 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 372373 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 372378 T1388 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 372472 T1350 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 372476 T1350 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:48047
[junit4:junit4] 2> 372477 T1350 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 372477 T1350 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 372478 T1350 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372386349102
[junit4:junit4] 2> 372478 T1350 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372386349102/solr.xml
[junit4:junit4] 2> 372478 T1350 oasc.CoreContainer.<init> New CoreContainer 581671744
[junit4:junit4] 2> 372479 T1350 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372386349102/'
[junit4:junit4] 2> 372479 T1350 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372386349102/'
[junit4:junit4] 2> ASYNC NEW_CORE C1409 name=collection1 org.apache.solr.core.SolrCore@58e34bb3 url=http://127.0.0.1:40211/collection1 node=127.0.0.1:40211_ C1409_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:40211_, base_url=http://127.0.0.1:40211}
[junit4:junit4] 2> 372488 T1411 C1409 P40211 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:46289/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 372489 T1411 C1409 P40211 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40211 START replicas=[http://127.0.0.1:46289/collection1/] nUpdates=100
[junit4:junit4] 2> 372489 T1411 C1409 P40211 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 372490 T1411 C1409 P40211 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 372490 T1411 C1409 P40211 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 372490 T1411 C1409 P40211 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 372490 T1411 C1409 P40211 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 372490 T1411 C1409 P40211 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:46289/collection1/. core=collection1
[junit4:junit4] 2> 372491 T1411 C1409 P40211 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1410 name=collection1 org.apache.solr.core.SolrCore@51034667 url=http://127.0.0.1:46289/collection1 node=127.0.0.1:46289_ C1410_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:46289_, base_url=http://127.0.0.1:46289, leader=true}
[junit4:junit4] 2> 372496 T1386 C1410 P46289 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 372498 T1386 C1410 P46289 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 372499 T1386 C1410 P46289 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10a9c47e lockFactory=org.apache.lucene.store.NativeFSLockFactory@72957363),segFN=segments_1,generation=1}
[junit4:junit4] 2> 372500 T1386 C1410 P46289 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 372500 T1386 C1410 P46289 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 372500 T1386 C1410 P46289 oass.SolrIndexSearcher.<init> Opening Searcher@6436b24 realtime
[junit4:junit4] 2> 372501 T1386 C1410 P46289 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 372501 T1386 C1410 P46289 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 3
[junit4:junit4] 2> 372502 T1411 C1409 P40211 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 372502 T1411 C1409 P40211 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 372504 T1386 C1410 P46289 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 372504 T1386 C1410 P46289 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 372505 T1411 C1409 P40211 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 372505 T1411 C1409 P40211 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 372505 T1411 C1409 P40211 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 372505 T1411 C1409 P40211 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 372507 T1411 C1409 P40211 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 372552 T1350 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 372552 T1350 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 372553 T1350 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 372553 T1350 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 372553 T1350 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 372554 T1350 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 372554 T1350 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 372554 T1350 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 372554 T1350 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 372555 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 372557 T1350 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 372558 T1350 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:42345/solr
[junit4:junit4] 2> 372558 T1350 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 372559 T1350 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 372560 T1441 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@53bdd8b5 name:ZooKeeperConnection Watcher:127.0.0.1:42345 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 372561 T1350 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 372562 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 372566 T1350 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 372567 T1443 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16665884 name:ZooKeeperConnection Watcher:127.0.0.1:42345/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 372567 T1350 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 372570 T1350 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 372835 T1373 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 372836 T1373 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node3",
[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:53246_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53246"}
[junit4:junit4] 2> 372839 T1373 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node2",
[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:40211_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40211"}
[junit4:junit4] 2> 372843 T1408 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> 372843 T1425 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> 372843 T1443 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> 372843 T1392 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> 372843 T1372 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> 372843 T1379 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> 373379 T1388 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node3, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 373379 T1388 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node3&state=recovering&nodeName=127.0.0.1:53246_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 373572 T1350 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:48047_
[junit4:junit4] 2> 373574 T1350 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:48047_
[junit4:junit4] 2> 373575 T1425 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> 373576 T1408 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> 373576 T1443 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> 373577 T1392 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 373577 T1372 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 373577 T1379 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 373578 T1372 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> 373578 T1392 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> 373578 T1379 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> 373578 T1425 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 373579 T1408 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 373580 T1443 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 373585 T1444 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 373585 T1444 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 373586 T1444 oasc.ZkController.waitForCoreNodeName look for our core node name
[junit4:junit4] 2> 374350 T1373 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 374350 T1373 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node4",
[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:48047_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48047"}
[junit4:junit4] 2> 374351 T1373 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 374351 T1373 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard shard=shard1
[junit4:junit4] 2> 374356 T1425 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> 374356 T1408 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> 374356 T1392 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> 374356 T1379 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> 374356 T1443 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> 374356 T1372 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> 374587 T1444 oasc.ZkController.waitForShardId waiting to find shard id in clusterstate for collection1
[junit4:junit4] 2> 374587 T1444 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372386349102/collection1
[junit4:junit4] 2> 374587 T1444 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 374588 T1444 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 374588 T1444 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 374589 T1444 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372386349102/collection1/'
[junit4:junit4] 2> 374590 T1444 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372386349102/collection1/lib/README' to classloader
[junit4:junit4] 2> 374590 T1444 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372386349102/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 374634 T1444 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 374669 T1444 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 374671 T1444 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 374675 T1444 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 375041 T1444 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 375046 T1444 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 375049 T1444 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 375060 T1444 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 375063 T1444 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 375065 T1444 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 375066 T1444 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 375066 T1444 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 375067 T1444 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 375067 T1444 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 375068 T1444 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 375068 T1444 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 375068 T1444 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372386349102/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty4/
[junit4:junit4] 2> 375068 T1444 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@63d625cf
[junit4:junit4] 2> 375069 T1444 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty4
[junit4:junit4] 2> 375069 T1444 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty4/index/
[junit4:junit4] 2> 375069 T1444 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 375069 T1444 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty4/index
[junit4:junit4] 2> 375071 T1444 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@62043116 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7522ed1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 375071 T1444 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 375073 T1444 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 375073 T1444 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 375073 T1444 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 375074 T1444 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 375074 T1444 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 375074 T1444 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 375075 T1444 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 375075 T1444 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 375075 T1444 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 375078 T1444 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 375080 T1444 oass.SolrIndexSearcher.<init> Opening Searcher@4c209916 main
[junit4:junit4] 2> 375080 T1444 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 375080 T1444 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 375084 T1445 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4c209916 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 375086 T1444 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 375086 T1444 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:48047 collection:collection1 shard:shard1
[junit4:junit4] 2> 375088 T1444 oasc.ZkController.register We are http://127.0.0.1:48047/collection1/ and leader is http://127.0.0.1:46289/collection1/
[junit4:junit4] 2> 375089 T1444 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:48047
[junit4:junit4] 2> 375089 T1444 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 375089 T1444 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1411 name=collection1 org.apache.solr.core.SolrCore@f431c0f url=http://127.0.0.1:48047/collection1 node=127.0.0.1:48047_ C1411_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:48047_, base_url=http://127.0.0.1:48047}
[junit4:junit4] 2> 375089 T1446 C1411 P48047 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 375090 T1444 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 375090 T1446 C1411 P48047 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 375090 T1446 C1411 P48047 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 375090 T1446 C1411 P48047 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 375091 T1350 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 375091 T1350 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 375091 T1446 C1411 P48047 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 375091 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 375095 T1387 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 375095 T1350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 375097 T1350 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 30 for each attempt
[junit4:junit4] 2> 375097 T1350 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):30
[junit4:junit4] 2> 375098 T1350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C1412 name=collection1 org.apache.solr.core.SolrCore@58959f4f url=http://127.0.0.1:53246/collection1 node=127.0.0.1:53246_ C1412_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:53246_, base_url=http://127.0.0.1:53246}
[junit4:junit4] 2> 375380 T1428 C1412 P53246 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:46289/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 375381 T1428 C1412 P53246 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53246 START replicas=[http://127.0.0.1:46289/collection1/] nUpdates=100
[junit4:junit4] 2> 375381 T1428 C1412 P53246 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 375382 T1428 C1412 P53246 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 375382 T1428 C1412 P53246 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 375382 T1428 C1412 P53246 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 375382 T1428 C1412 P53246 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 375382 T1428 C1412 P53246 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:46289/collection1/. core=collection1
[junit4:junit4] 2> 375383 T1428 C1412 P53246 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1413 name=collection1 org.apache.solr.core.SolrCore@51034667 url=http://127.0.0.1:46289/collection1 node=127.0.0.1:46289_ C1413_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:46289_, base_url=http://127.0.0.1:46289, leader=true}
[junit4:junit4] 2> 375384 T1385 C1413 P46289 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 375387 T1386 C1413 P46289 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 375388 T1386 C1413 P46289 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 375388 T1386 C1413 P46289 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 375388 T1386 C1413 P46289 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> ASYNC NEW_CORE C1414 name=collection1 org.apache.solr.core.SolrCore@58959f4f url=http://127.0.0.1:53246/collection1 node=127.0.0.1:53246_ C1414_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:53246_, base_url=http://127.0.0.1:53246}
[junit4:junit4] 2> 375397 T1428 C1414 P53246 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 375397 T1428 C1414 P53246 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> ASYNC NEW_CORE C1415 name=collection1 org.apache.solr.core.SolrCore@51034667 url=http://127.0.0.1:46289/collection1 node=127.0.0.1:46289_ C1415_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:46289_, base_url=http://127.0.0.1:46289, leader=true}
[junit4:junit4] 2> 375400 T1385 C1415 P46289 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 375401 T1428 C1414 P53246 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 375401 T1428 C1414 P53246 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 375401 T1428 C1414 P53246 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 375401 T1428 C1414 P53246 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 375402 T1428 C1414 P53246 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 375861 T1373 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 375862 T1373 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node4",
[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:48047_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48047"}
[junit4:junit4] 2> 375865 T1373 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node3",
[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:53246_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53246"}
[junit4:junit4] 2> 375869 T1379 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> 375869 T1372 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> 375869 T1392 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> 375869 T1443 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> 375869 T1408 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> 375869 T1425 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> 376096 T1387 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: core_node4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 376096 T1387 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=core_node4&state=recovering&nodeName=127.0.0.1:48047_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 376099 T1350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 377101 T1350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C1416 name=collection1 org.apache.solr.core.SolrCore@f431c0f url=http://127.0.0.1:48047/collection1 node=127.0.0.1:48047_ C1416_STATE=coll:collection1 core:collection1 props:{state=recovering, core=collection1, node_name=127.0.0.1:48047_, base_url=http://127.0.0.1:48047}
[junit4:junit4] 2> 378097 T1446 C1416 P48047 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:46289/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 378097 T1446 C1416 P48047 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:48047 START replicas=[http://127.0.0.1:46289/collection1/] nUpdates=100
[junit4:junit4] 2> 378098 T1446 C1416 P48047 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 378098 T1446 C1416 P48047 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 378098 T1446 C1416 P48047 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 378098 T1446 C1416 P48047 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 378099 T1446 C1416 P48047 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 378099 T1446 C1416 P48047 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:46289/collection1/. core=collection1
[junit4:junit4] 2> 378099 T1446 C1416 P48047 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 378100 T1388 C1415 P46289 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 378102 T1350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 378104 T1386 C1415 P46289 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 378104 T1386 C1415 P46289 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 378104 T1386 C1415 P46289 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 378105 T1386 C1415 P46289 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> 378105 T1446 C1416 P48047 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 378106 T1446 C1416 P48047 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 378108 T1388 C1415 P46289 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 378109 T1446 C1416 P48047 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 378109 T1446 C1416 P48047 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 378109 T1446 C1416 P48047 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 378109 T1446 C1416 P48047 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 378110 T1446 C1416 P48047 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 378877 T1373 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 378878 T1373 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node4",
[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:48047_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:48047"}
[junit4:junit4] 2> 378881 T1425 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> 378882 T1392 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> 378882 T1379 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> 378881 T1408 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> 378882 T1372 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> 378882 T1443 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> 379104 T1350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 379105 T1350 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C1417 name=collection1 org.apache.solr.core.SolrCore@3cf5d095 url=http://127.0.0.1:55834/collection1 node=127.0.0.1:55834_ C1417_STATE=coll:control_collection core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:55834_, base_url=http://127.0.0.1:55834, leader=true}
[junit4:junit4] 2> 379110 T1365 C1417 P55834 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 379112 T1365 C1417 P55834 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3080dfc0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a78eb4f),segFN=segments_1,generation=1}
[junit4:junit4] 2> 379113 T1365 C1417 P55834 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 379113 T1365 C1417 P55834 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 379113 T1365 C1417 P55834 oass.SolrIndexSearcher.<init> Opening Searcher@373f76ad main
[junit4:junit4] 2> 379114 T1365 C1417 P55834 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 379114 T1376 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@373f76ad main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 379115 T1365 C1417 P55834 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> ASYNC NEW_CORE C1418 name=collection1 org.apache.solr.core.SolrCore@58e34bb3 url=http://127.0.0.1:40211/collection1 node=127.0.0.1:40211_ C1418_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:40211_, base_url=http://127.0.0.1:40211}
[junit4:junit4] 2> 379122 T1404 C1418 P40211 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:46289/collection1/, StdNode: http://127.0.0.1:40211/collection1/, StdNode: http://127.0.0.1:53246/collection1/, StdNode: http://127.0.0.1:48047/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 379125 T1403 C1418 P40211 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 379126 T1387 C1415 P46289 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 379126 T1387 C1415 P46289 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 379127 T1387 C1415 P46289 oass.SolrIndexSearcher.<init> Opening Searcher@77f05589 main
[junit4:junit4] 2> 379127 T1387 C1415 P46289 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 379129 T1394 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@77f05589 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 379129 T1403 C1418 P40211 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6db20cfc lockFactory=org.apache.lucene.store.NativeFSLockFactory@37ad4409),segFN=segments_1,generation=1}
[junit4:junit4] 2> C1416_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:48047_, base_url=http://127.0.0.1:48047}
[junit4:junit4] 2> 379129 T1438 C1416 P48047 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 379130 T1403 C1418 P40211 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 379129 T1387 C1415 P46289 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 3
[junit4:junit4] 2> 379130 T1403 C1418 P40211 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 379131 T1438 C1416 P48047 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@62043116 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7522ed1),segFN=segments_1,generation=1}
[junit4:junit4] 2> C1414_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:53246_, base_url=http://127.0.0.1:53246}
[junit4:junit4] 2> 379130 T1421 C1414 P53246 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 379131 T1438 C1416 P48047 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 379131 T1403 C1418 P40211 oass.SolrIndexSearcher.<init> Opening Searcher@64fc71cd main
[junit4:junit4] 2> 379132 T1438 C1416 P48047 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 379133 T1421 C1414 P53246 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@11cd34fe lockFactory=org.apache.lucene.store.NativeFSLockFactory@25920678),segFN=segments_1,generation=1}
[junit4:junit4] 2> 379133 T1403 C1418 P40211 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 379133 T1421 C1414 P53246 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 379133 T1410 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@64fc71cd main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 379134 T1421 C1414 P53246 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 379133 T1438 C1416 P48047 oass.SolrIndexSearcher.<init> Opening Searcher@7722267 main
[junit4:junit4] 2> 379134 T1421 C1414 P53246 oass.SolrIndexSearcher.<init> Opening Searcher@543b9ff2 main
[junit4:junit4] 2> 379134 T1403 C1418 P40211 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> 379135 T1421 C1414 P53246 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 379134 T1438 C1416 P48047 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 379135 T1427 oasc.JmxMonitoredMap.put WARN Failed to register info bean: fieldValueCache javax.management.InstanceAlreadyExistsException: solr/collection1:type=fieldValueCache,id=org.apache.solr.search.FastLRUCache
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:140)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4] 2> at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:309)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1844)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.access$000(SolrCore.java:135)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1721)
[junit4:junit4] 2> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[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.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 379136 T1427 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@543b9ff2 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 379135 T1445 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7722267 main{StandardDirectoryReader(segments_1:1:nrt)}
[junit4:junit4] 2> 379136 T1421 C1414 P53246 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> 379137 T1438 C1416 P48047 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 379137 T1404 C1418 P40211 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 16
[junit4:junit4] 2> 379138 T1350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 379140 T1386 C1415 P46289 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 379142 T1401 C1418 P40211 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 379144 T1419 C1414 P53246 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 379146 T1436 C1416 P48047 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 381151 T1366 C1417 P55834 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1439051397595136000)} 0 1
[junit4:junit4] 2> 381161 T1435 C1416 P48047 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1439051397601427456&update.from=http://127.0.0.1:46289/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439051397601427456)} 0 1
[junit4:junit4] 2> 381164 T1402 C1418 P40211 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1439051397601427456&update.from=http://127.0.0.1:46289/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439051397601427456)} 0 2
[junit4:junit4] 2> 381164 T1419 C1414 P53246 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1439051397601427456&update.from=http://127.0.0.1:46289/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1439051397601427456)} 0 1
[junit4:junit4] 2> 381165 T1386 C1415 P46289 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1439051397601427456)} 0 9
[junit4:junit4] 2> 381165 T1401 C1418 P40211 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:*} 0 12
[junit4:junit4] 2> 381169 T1365 C1417 P55834 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1439051397614010368)]} 0 1
[junit4:junit4] 2> 381178 T1403 C1418 P40211 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46289/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1439051397620301824)]} 0 1
[junit4:junit4] 2> 381178 T1436 C1416 P48047 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46289/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1439051397620301824)]} 0 1
[junit4:junit4] 2> 381178 T1418 C1414 P53246 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46289/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1439051397620301824)]} 0 1
[junit4:junit4] 2> 381179 T1388 C1415 P46289 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53246/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1439051397620301824)]} 0 6
[junit4:junit4] 2> 381179 T1420 C1414 P53246 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0]} 0 8
[junit4:junit4] 2> 381182 T1367 C1417 P55834 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1439051397628690432)]} 0 1
[junit4:junit4] 2> 381190 T1421 C1414 P53246 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46289/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439051397632884736)]} 0 1
[junit4:junit4] 2> 381190 T1437 C1416 P48047 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46289/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439051397632884736)]} 0 1
[junit4:junit4] 2> 381192 T1402 C1418 P40211 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46289/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1439051397632884736)]} 0 1
[junit4:junit4] 2> 381192 T1387 C1415 P46289 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40211/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1439051397632884736)]} 0 6
[junit4:junit4] 2> 381193 T1404 C1418 P40211 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1]} 0 9
[junit4:junit4] 2> 381196 T1368 C1417 P55834 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1439051397642321920)]} 0 1
[junit4:junit4] 2> 381198 T1386 C1415 P46289 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:40211/collection1/]
[junit4:junit4] 2> 381198 T1386 C1415 P46289 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:40211/collection1/ against:[http://127.0.0.1:40211/collection1/] result:true
[junit4:junit4] 2> 381199 T1386 C1415 P46289 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:53246/collection1/ against:[http://127.0.0.1:40211/collection1/] result:false
[junit4:junit4] 2> 381199 T1386 C1415 P46289 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:48047/collection1/ against:[http://127.0.0.1:40211/collection1/] result:false
[junit4:junit4] 2> 381202 T1419 C1414 P53246 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46289/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:40211/collection1/&wt=javabin&version=2} {add=[2 (1439051397646516224)]} 0 0
[junit4:junit4] 2> 381203 T1438 C1416 P48047 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46289/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:40211/collection1/&wt=javabin&version=2} {add=[2 (1439051397646516224)]} 0 1
[junit4:junit4] 2> 381203 T1386 C1415 P46289 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:40211/collection1/&wt=javabin&version=2} {add=[2 (1439051397646516224)]} 0 5
[junit4:junit4] 2> 381207 T1366 C1417 P55834 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1439051397653856256)]} 0 2
[junit4:junit4] 2> 381210 T1388 C1415 P46289 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:40211/collection1/]
[junit4:junit4] 2> 381211 T1388 C1415 P46289 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:40211/collection1/ against:[http://127.0.0.1:40211/collection1/] result:true
[junit4:junit4] 2> 381211 T1388 C1415 P46289 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:53246/collection1/ against:[http://127.0.0.1:40211/collection1/] result:false
[junit4:junit4] 2> 381212 T1388 C1415 P46289 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:48047/collection1/ against:[http://127.0.0.1:40211/collection1/] result:false
[junit4:junit4] 2> 381216 T1436 C1416 P48047 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46289/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:40211/collection1/&wt=javabin&version=2} {add=[3 (1439051397660147712)]} 0 1
[junit4:junit4] 2> 381216 T1418 C1414 P53246 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46289/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:40211/collection1/&wt=javabin&version=2} {add=[3 (1439051397660147712)]} 0 1
[junit4:junit4] 2> 381217 T1388 C1415 P46289 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:48047/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:40211/collection1/&wt=javabin&version=2} {add=[3 (1439051397660147712)]} 0 7
[junit4:junit4] 2> 381217 T1435 C1416 P48047 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:40211/collection1/&test.distrib.skip.servers=http://127.0.0.1:53246/collection1/&wt=javabin&version=2} {add=[3]} 0 9
[junit4:junit4] 2> 381220 T1365 C1417 P55834 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 381224 T1365 C1417 P55834 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3080dfc0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a78eb4f),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3080dfc0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a78eb4f),segFN=segments_2,generation=2}
[junit4:junit4] 2> 381225 T1365 C1417 P55834 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 381227 T1365 C1417 P55834 oass.SolrIndexSearcher.<init> Opening Searcher@25724c48 main
[junit4:junit4] 2> 381227 T1365 C1417 P55834 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 381228 T1376 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@25724c48 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 381229 T1365 C1417 P55834 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 381231 T1387 C1415 P46289 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:46289/collection1/, StdNode: http://127.0.0.1:40211/collection1/, StdNode: http://127.0.0.1:53246/collection1/, StdNode: http://127.0.0.1:48047/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 381233 T1385 C1415 P46289 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 381235 T1420 C1414 P53246 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 381235 T1401 C1418 P40211 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 381235 T1437 C1416 P48047 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C1419 name=collection1 org.apache.solr.core.SolrCore@58959f4f url=http://127.0.0.1:53246/collection1 node=127.0.0.1:53246_ C1419_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:53246_, base_url=http://127.0.0.1:53246}
[junit4:junit4] 2> 381251 T1420 C1419 P53246 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@11cd34fe lockFactory=org.apache.lucene.store.NativeFSLockFactory@25920678),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@11cd34fe lockFactory=org.apache.lucene.store.NativeFSLockFactory@25920678),segFN=segments_2,generation=2}
[junit4:junit4] 2> ASYNC NEW_CORE C1420 name=collection1 org.apache.solr.core.SolrCore@58e34bb3 url=http://127.0.0.1:40211/collection1 node=127.0.0.1:40211_ C1420_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:40211_, base_url=http://127.0.0.1:40211}
[junit4:junit4] 2> 381252 T1401 C1420 P40211 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6db20cfc lockFactory=org.apache.lucene.store.NativeFSLockFactory@37ad4409),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6db20cfc lockFactory=org.apache.lucene.store.NativeFSLockFactory@37ad4409),segFN=segments_2,generation=2}
[junit4:junit4] 2> 381253 T1401 C1420 P40211 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 381252 T1420 C1419 P53246 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> ASYNC NEW_CORE C1421 name=collection1 org.apache.solr.core.SolrCore@f431c0f url=http://127.0.0.1:48047/collection1 node=127.0.0.1:48047_ C1421_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:48047_, base_url=http://127.0.0.1:48047}
[junit4:junit4] 2> 381253 T1437 C1421 P48047 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@62043116 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7522ed1),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@62043116 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7522ed1),segFN=segments_2,generation=2}
[junit4:junit4] 2> 381254 T1437 C1421 P48047 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> ASYNC NEW_CORE C1422 name=collection1 org.apache.solr.core.SolrCore@51034667 url=http://127.0.0.1:46289/collection1 node=127.0.0.1:46289_ C1422_STATE=coll:collection1 core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:46289_, base_url=http://127.0.0.1:46289, leader=true}
[junit4:junit4] 2> 381254 T1385 C1422 P46289 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10a9c47e lockFactory=org.apache.lucene.store.NativeFSLockFactory@72957363),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10a9c47e lockFactory=org.apache.lucene.store.NativeFSLockFactory@72957363),segFN=segments_2,generation=2}
[junit4:junit4] 2> 381254 T1385 C1422 P46289 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 381254 T1420 C1419 P53246 oass.SolrIndexSearcher.<init> Opening Searcher@69ae252b main
[junit4:junit4] 2> 381255 T1420 C1419 P53246 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 381256 T1427 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@69ae252b main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 381256 T1437 C1421 P48047 oass.SolrIndexSearcher.<init> Opening Searcher@256c6a17 main
[junit4:junit4] 2> 381256 T1420 C1419 P53246 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 22
[junit4:junit4] 2> 381256 T1437 C1421 P48047 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 381257 T1401 C1420 P40211 oass.SolrIndexSearcher.<init> Opening Searcher@1ac0970d main
[junit4:junit4] 2> 381257 T1445 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@256c6a17 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 381257 T1401 C1420 P40211 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 381258 T1437 C1421 P48047 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 23
[junit4:junit4] 2> 381258 T1410 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ac0970d main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c2)}
[junit4:junit4] 2> 381258 T1385 C1422 P46289 oass.SolrIndexSearcher.<init> Opening Searcher@65440baf main
[junit4:junit4] 2> 381259 T1385 C1422 P46289 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 381259 T1401 C1420 P40211 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4] 2> 381259 T1394 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@65440baf main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 381260 T1385 C1422 P46289 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 27
[junit4:junit4] 2> 381260 T1387 C1422 P46289 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 29
[junit4:junit4] 2> 381261 T1350 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):330
[junit4:junit4] 2> 381261 T1350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 381262 T1350 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 381264 T1386 C1422 P46289 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 381267 T1403 C1420 P40211 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=2 status=0 QTime=1
[junit4:junit4] 2> 381269 T1421 C1419 P53246 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 381271 T1438 C1421 P48047 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 381273 T1350 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 381277 T1418 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2
[junit4:junit4] 2> 381278 T1418 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 381282 T1388 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 381282 T1388 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:46289/collection1/
[junit4:junit4] 2> 381282 T1388 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:46289 START replicas=[http://127.0.0.1:40211/collection1/, http://127.0.0.1:53246/collection1/, http://127.0.0.1:48047/collection1/] nUpdates=100
[junit4:junit4] 2> 381284 T1402 C1420 P40211 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 381284 T1436 C1421 P48047 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 381284 T1420 C1419 P53246 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 381284 T1388 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:46289 Received 3 versions from 127.0.0.1:40211/collection1/
[junit4:junit4] 2> 381285 T1388 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:46289 Our versions are newer. ourLowThreshold=1439051397601427456 otherHigh=1439051397632884736
[junit4:junit4] 2> 381285 T1388 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:46289 Received 5 versions from 127.0.0.1:48047/collection1/
[junit4:junit4] 2> 381285 T1388 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:46289 Our versions are newer. ourLowThreshold=1439051397601427456 otherHigh=1439051397646516224
[junit4:junit4] 2> 381286 T1388 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:46289 Received 5 versions from 127.0.0.1:53246/collection1/
[junit4:junit4] 2> 381286 T1388 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:46289 Our versions are newer. ourLowThreshold=1439051397601427456 otherHigh=1439051397646516224
[junit4:junit4] 2> 381286 T1388 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:46289 DONE. sync succeeded
[junit4:junit4] 2> 381286 T1388 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 381286 T1388 oasc.SyncStrategy.syncToMe http://127.0.0.1:46289/collection1/: try and ask http://127.0.0.1:40211/collection1/ to sync
[junit4:junit4] 2> 381287 T1388 oasc.SyncStrategy.syncToMe http://127.0.0.1:46289/collection1/: try and ask http://127.0.0.1:53246/collection1/ to sync
[junit4:junit4] 2> 381287 T1388 oasc.SyncStrategy.syncToMe http://127.0.0.1:46289/collection1/: try and ask http://127.0.0.1:48047/collection1/ to sync
[junit4:junit4] 2> 381288 T1404 C1420 P40211 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40211 START replicas=[http://127.0.0.1:46289/collection1/] nUpdates=100
[junit4:junit4] 2> 381288 T1421 C1419 P53246 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53246 START replicas=[http://127.0.0.1:46289/collection1/] nUpdates=100
[junit4:junit4] 2> 381288 T1435 C1421 P48047 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:48047 START replicas=[http://127.0.0.1:46289/collection1/] nUpdates=100
[junit4:junit4] 2> 381289 T1385 C1422 P46289 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 381290 T1421 C1419 P53246 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:53246 Received 5 versions from 127.0.0.1:46289/collection1/
[junit4:junit4] 2> 381290 T1421 C1419 P53246 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:53246 Our versions are newer. ourLowThreshold=1439051397601427456 otherHigh=1439051397646516224
[junit4:junit4] 2> 381290 T1421 C1419 P53246 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53246 DONE. sync succeeded
[junit4:junit4] 2> 381290 T1385 C1422 P46289 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 381290 T1387 C1422 P46289 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 381291 T1404 C1420 P40211 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:40211 Received 5 versions from 127.0.0.1:46289/collection1/
[junit4:junit4] 2> 381291 T1421 C1419 P53246 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:46289/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=3
[junit4:junit4] 2> 381291 T1404 C1420 P40211 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:40211 Requesting updates from 127.0.0.1:46289/collection1/n=2 versions=[1439051397660147712, 1439051397646516224]
[junit4:junit4] 2> 381291 T1435 C1421 P48047 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:48047 Received 5 versions from 127.0.0.1:46289/collection1/
[junit4:junit4] 2> 381292 T1435 C1421 P48047 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:48047 Our versions are newer. ourLowThreshold=1439051397601427456 otherHigh=1439051397646516224
[junit4:junit4] 2> 381293 T1435 C1421 P48047 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:48047 DONE. sync succeeded
[junit4:junit4] 2> 381293 T1388 oasc.SyncStrategy.syncToMe http://127.0.0.1:46289/collection1/: sync completed with http://127.0.0.1:53246/collection1/
[junit4:junit4] 2> 381293 T1435 C1421 P48047 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:46289/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=5
[junit4:junit4] 2> 381294 T1388 oasc.SyncStrategy.syncToMe http://127.0.0.1:46289/collection1/: sync completed with http://127.0.0.1:48047/collection1/
[junit4:junit4] 2> 381297 T1386 C1422 P46289 oasc.SolrCore.execute [collection1] webapp= path=/get params={distrib=false&getUpdates=1439051397660147712,1439051397646516224&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 381300 T1404 C1420 P40211 oasup.LogUpdateProcessor.finish [collection1] {add=[2 (1439051397646516224), 3 (1439051397660147712)]} 0 2
[junit4:junit4] 2> 381300 T1404 C1420 P40211 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40211 DONE. sync succeeded
[junit4:junit4] 2> 381300 T1404 C1420 P40211 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:46289/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=12
[junit4:junit4] 2> 381301 T1388 oasc.SyncStrategy.syncToMe http://127.0.0.1:46289/collection1/: sync completed with http://127.0.0.1:40211/collection1/
[junit4:junit4] 2> 381301 T1388 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=20
[junit4:junit4] 2> 381302 T1418 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/collections params={shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2} status=0 QTime=26
[junit4:junit4] 2> 381302 T1350 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 381303 T1350 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 381303 T1350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 381304 T1350 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C1423 name=collection1 org.apache.solr.core.SolrCore@3cf5d095 url=http://127.0.0.1:55834/collection1 node=127.0.0.1:55834_ C1423_STATE=coll:control_collection core:collection1 props:{state=active, core=collection1, node_name=127.0.0.1:55834_, base_url=http://127.0.0.1:55834, leader=true}
[junit4:junit4] 2> 381306 T1367 C1423 P55834 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 381306 T1367 C1423 P55834 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 381307 T1367 C1423 P55834 oass.SolrIndexSearcher.<init> Opening Searcher@f471853 main
[junit4:junit4] 2> 381307 T1367 C1423 P55834 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 381308 T1376 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@f471853 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 381308 T1367 C1423 P55834 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 2
[junit4:junit4] 2> 381311 T1385 C1422 P46289 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:46289/collection1/, StdNode: http://127.0.0.1:40211/collection1/, StdNode: http://127.0.0.1:53246/collection1/, StdNode: http://127.0.0.1:48047/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 381313 T1419 C1419 P53246 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 381313 T1387 C1422 P46289 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 381313 T1437 C1421 P48047 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 381313 T1401 C1420 P40211 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 381314 T1437 C1421 P48047 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 381314 T1387 C1422 P46289 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 381314 T1419 C1419 P53246 oasu.DirectUpdateHandler2.commit No uncommitted changes. Skipping IW.commit.
[junit4:junit4] 2> 381315 T1387 C1422 P46289 oass.SolrIndexSearcher.<init> Opening Searcher@35bb02f1 main
[junit4:junit4] 2> 381315 T1437 C1421 P48047 oass.SolrIndexSearcher.<init> Opening Searcher@6e1d3507 main
[junit4:junit4] 2> 381316 T1387 C1422 P46289 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 381316 T1445 oasc.JmxMonitoredMap.put WARN Failed to register info bean: searcher javax.management.InstanceAlreadyExistsException: solr/collection1:type=searcher,id=org.apache.solr.search.SolrIndexSearcher
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:140)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4] 2> at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:305)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1844)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.access$000(SolrCore.java:135)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1721)
[junit4:junit4] 2> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[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.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 381317 T1445 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6e1d3507 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 381315 T1419 C1419 P53246 oass.SolrIndexSearcher.<init> Opening Searcher@34054f87 main
[junit4:junit4] 2> 381316 T1394 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@35bb02f1 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 381318 T1437 C1421 P48047 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 381318 T1419 C1419 P53246 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 381318 T1387 C1422 P46289 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> 381319 T1401 C1420 P40211 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6db20cfc lockFactory=org.apache.lucene.store.NativeFSLockFactory@37ad4409),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@6db20cfc lockFactory=org.apache.lucene.store.NativeFSLockFactory@37ad4409),segFN=segments_3,generation=3}
[junit4:junit4] 2> 381318 T1437 C1421 P48047 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> 381319 T1401 C1420 P40211 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 381319 T1427 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@34054f87 main{StandardDirectoryReader(segments_2:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 381320 T1419 C1419 P53246 oasup.LogUpdateProcessor.finish [collection1] webapp= 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> 381321 T1401 C1420 P40211 oass.SolrIndexSearcher.<init> Opening Searcher@4c4d75aa main
[junit4:junit4] 2> 381322 T1401 C1420 P40211 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 381322 T1410 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4c4d75aa main{StandardDirectoryReader(segments_3:5:nrt _0(5.0):c2 _1(5.0):c2)}
[junit4:junit4] 2> 381323 T1401 C1420 P40211 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 10
[junit4:junit4] 2> 381323 T1385 C1422 P46289 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 12
[junit4:junit4] 2> 381324 T1350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 381327 T1386 C1422 P46289 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 381329 T1403 C1420 P40211 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 381331 T1420 C1419 P53246 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 381334 T1438 C1421 P48047 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 383335 T1350 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> check const of shard1
[junit4:junit4] 2> client0
[junit4:junit4] 2> PROPS:core_node1:{"state":"active","core":"collection1","node_name":"127.0.0.1:46289_","base_url":"http://127.0.0.1:46289","leader":"true"}
[junit4:junit4] 2> 383339 T1385 C1422 P46289 oasc.SolrCore.execute [collection1] webapp= 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> client1
[junit4:junit4] 2> PROPS:core_node2:{"state":"active","core":"collection1","node_name":"127.0.0.1:40211_","base_url":"http://127.0.0.1:40211"}
[junit4:junit4] 2> 383341 T1403 C1420 P40211 oasc.SolrCore.execute [collection1] webapp= 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:core_node3:{"state":"active","core":"collection1","node_name":"127.0.0.1:53246_","base_url":"http://127.0.0.1:53246"}
[junit4:junit4] 2> 383344 T1419 C1419 P53246 oasc.SolrCore.execute [collection1] webapp= 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> client3
[junit4:junit4] 2> PROPS:core_node4:{"state":"active","core":"collection1","node_name":"127.0.0.1:48047_","base_url":"http://127.0.0.1:48047"}
[junit4:junit4] 2> 383346 T1437 C1421 P48047 oasc.SolrCore.execute [collection1] webapp= 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> 383349 T1386 C1422 P46289 oasc.SolrCore.execute [collection1] webapp= path=/select params={q=*:*&wt=javabin&version=2} hits=4 status=0 QTime=0
[junit4:junit4] 2> 383354 T1365 C1423 P55834 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1439051399904100352)]} 0 2
[junit4:junit4] 2> 383358 T1388 C1422 P46289 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:40211/collection1/]
[junit4:junit4] 2> 383359 T1388 C1422 P46289 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:40211/collection1/ against:[http://127.0.0.1:40211/collection1/] result:true
[junit4:junit4] 2> 383359 T1388 C1422 P46289 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:53246/collection1/ against:[http://127.0.0.1:40211/collection1/] result:false
[junit4:junit4] 2> 383359 T1388 C1422 P46289 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:48047/collection1/ against:[http://127.0.0.1:40211/collection1/] result:false
[junit4:junit4] 2> 383366 T1438 C1421 P48047 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46289/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:40211/collection1/&wt=javabin&version=2} {add=[4 (1439051399912488960)]} 0 3
[junit4:junit4] 2> 383366 T1421 C1419 P53246 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:46289/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:40211/collection1/&wt=javabin&version=2} {add=[4 (1439051399912488960)]} 0 3
[junit4:junit4] 2> 383367 T1388 C1422 P46289 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:40211/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:40211/collection1/&wt=javabin&version=2} {add=[4 (1439051399912488960)]} 0 9
[junit4:junit4] 2> 383367 T1402 C1420 P40211 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:40211/collection1/&wt=javabin&version=2} {add=[4]} 0 11
[junit4:junit4] 2> 383368 T1350 oasc.ChaosMonkey.monkeyLog monkey: kill shard! 46289
[junit4:junit4] 2> 383390 T1350 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=375753542
[junit4:junit4] 2> 384891 T1373 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 384891 T1373 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=null message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[junit4:junit4] 2> "shard":null,
[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:46289_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46289"}
[junit4:junit4] 2> 384892 T1373 oasc.Overseer$ClusterStateUpdater.updateState shard=shard1 is already registered
[junit4:junit4] 2> 384895 T1408 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> 384895 T1372 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> 384895 T1443 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> 384895 T1392 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> 384895 T1379 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> 384895 T1425 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> 386393 T1350 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 386393 T1350 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 386395 T1350 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@51034667
[junit4:junit4] 2> 386398 T1350 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> 386399 T1350 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 386399 T1350 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 386399 T1350 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 386399 T1373 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 386400 T1373 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"core_node1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[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:46289_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46289"}
[junit4:junit4] 2> C1422_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, node_name=127.0.0.1:46289_, base_url=http://127.0.0.1:46289, leader=true}
[junit4:junit4] 2> 386404 T1350 C1422 P46289 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10a9c47e lockFactory=org.apache.lucene.store.NativeFSLockFactory@72957363),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10a9c47e lockFactory=org.apache.lucene.store.NativeFSLockFactory@72957363),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@10a9c47e lockFactory=org.apache.lucene.store.NativeFSLockFactory@72957363),segFN=segments_3,generation=3}
[junit4:junit4] 2> 386405 T1350 C1422 P46289 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 386406 T1350 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 386407 T1350 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 386407 T1350 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty1 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty1;done=false>>]
[junit4:junit4] 2> 386407 T1350 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty1
[junit4:junit4] 2> 386407 T1350 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty1/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty1/index;done=false>>]
[junit4:junit4] 2> 386408 T1350 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.SyncSliceTest-1372386336906/jetty1/index
[junit4:junit4] 2> 386408 T1443 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> 386408 T1392 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> 386408 T1408 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> 386408 T1379 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> 386408 T1425 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> 386408 T1372 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> 386412 T1443 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> 386412 T1425 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> 386413 T1379 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 386413 T1379 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> 386413 T1350 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 386414 T1443 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 386414 T1372 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 386415 T1372 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> 386415 T1425 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 386416 T1408 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process for shard shard1
[junit4:junit4] 2> 386417 T1408 oasc.ShardLeaderElectionContext.shouldIBeLeader Checking if I should try and be the leader.
[junit4:junit4] 2> 386417 T1408 oasc.ShardLeaderElectionContext.shouldIBeLeader My last published State was Active, it's okay to be the leader.
[junit4:junit4] 2> 386418 T1408 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 386418 T1408 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:40211/collection1/
[junit4:junit4] 2> 386418 T1408 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40211 START replicas=[http://127.0.0.1:46289/collection1/, http://127.0.0.1:53246/collection1/, http://127.0.0.1:48047/collection1/] nUpdates=100
[junit4:junit4] 2> 386420 T1408 oasu.PeerSync.handleResponse WARN PeerSync: core=collection1 url=http://127.0.0.1:40211 couldn't connect to http://127.0.0.1:46289/collection1/, counting as success
[junit4:junit4] 2> 386421 T1420 C1419 P53246 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 386421 T1438 C1421 P48047 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 386422 T1408 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:40211 Received 6 versions from 127.0.0.1:53246/collection1/
[junit4:junit4] 2> 386422 T1408 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:40211 Requesting updates from 127.0.0.1:53246/collection1/n=1 versions=[1439051399912488960]
[junit4:junit4] 2> 386422 T1408 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:40211 Received 6 versions from 127.0.0.1:48047/collection1/
[junit4:junit4] 2> 386422 T1408 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:40211 Our versions are newer. ourLowThreshold=1439051397601427456 otherHigh=1439051397660147712
[junit4:junit4] 2> 386424 T1419 C1419 P53246 oasc.SolrCore.execute [collection1] webapp= path=/get params={distrib=false&getUpdates=1439051399912488960&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 386427 T1408 oasup.LogUpdateProcessor.finish [collection1] {add=[4 (1439051399912488960)]} 0 2
[junit4:junit4] 2> 386427 T1408 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40211 DONE. sync succeeded
[junit4:junit4] 2> 386427 T1408 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 386427 T1408 oasc.SyncStrategy.syncToMe http://127.0.0.1:40211/collection1/: try and ask http://127.0.0.1:46289/collection1/ to sync
[junit4:junit4] 2> 386428 T1408 oasc.SyncStrategy.syncToMe http://127.0.0.1:40211/collection1/: try and ask http://127.0.0.1:53246/collection1/ to sync
[junit4:junit4] 2> 386428 T1408 oasc.SyncStrategy.syncToMe http://127.0.0.1:40211/collection1/: try and ask http://127.0.0.1:48047/collection1/ to sync
[junit4:junit4] 2> 386428 T1408 oasc.SolrException.log ERROR Sync request error: org.apache.solr.client.solrj.SolrServerException: Server refused connection at: http://127.0.0.1:46289/collection1
[junit4:junit4] 2> 386429 T1408 oasc.SyncStrategy.syncToMe http://127.0.0.1:40211/collection1/: Sync failed - asking replica (http://127.0.0.1:46289/collection1/) to recover.
[junit4:junit4] 2> 386429 T1476 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 386430 T1436 C1421 P48047 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:48047 START replicas=[http://127.0.0.1:40211/collection1/] nUpdates=100
[junit4:junit4] 2> 386430 T1421 C1419 P53246 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53246 START replicas=[http://127.0.0.1:40211/collection1/] nUpdates=100
[junit4:junit4] 2> 386432 T1403 C1420 P40211 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 386432 T1402 C1420 P40211 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 386432 T1421 C1419 P53246 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:53246 Received 6 versions from 127.0.0.1:40211/collection1/
[junit4:junit4] 2> 386433 T1476 oasc.SolrException.log ERROR http://127.0.0.1:40211/collection1/: Could not tell a replica to recover:org.apache.solr.client.solrj.SolrServerException: Server refused connection at: http://127.0.0.1:46289
[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:297)
[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.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2> Caused by: org.apache.http.conn.HttpHostConnectException: Connection to http://127.0.0.1:46289 refused
[junit4:junit4] 2> at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:190)
[junit4:junit4] 2> at org.apache.http.impl.conn.ManagedClientConnectionImpl.open(ManagedClientConnectionImpl.java:294)
[junit4:junit4] 2> at org.apache.http.impl.client.DefaultRequestDirector.tryCon
[...truncated too long message...]
1",
[junit4:junit4] 1> "node_name":"127.0.0.1:48047_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:48047",
[junit4:junit4] 1> "leader":"true"}}}},
[junit4:junit4] 1> "router":"compositeId"},
[junit4:junit4] 1> "control_collection":{
[junit4:junit4] 1> "shards":{"shard1":{
[junit4:junit4] 1> "range":"80000000-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{"core_node1":{
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:55834_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:55834",
[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:53246_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:48047_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:55834_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:46289_ (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/89940710975668236-core_node4-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89940710975668234-core_node3-n_0000000005 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89940710975668238-core_node1-n_0000000004 (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:48047_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:48047"}
[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/89940710975668227-core_node1-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:55834_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:55834"}
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (4)
[junit4:junit4] 1> /solr/overseer_elect/election/89940710975668234-127.0.0.1:53246_-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89940710975668236-127.0.0.1:48047_-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89940710975668227-127.0.0.1:55834_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89940710975668238-127.0.0.1:46289_-n_0000000005 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89940710975668227-127.0.0.1:55834_-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=EFFBC37F60AB5480 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_AE -Dtests.timezone=America/New_York -Dtests.file.encoding=US-ASCII
[junit4:junit4] FAILURE 99.8s J0 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:46289/collection1lastClient and got 253 from http://127.0.0.1:53246/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([EFFBC37F60AB5480:6E1D4D6717F434BC]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1045)
[junit4:junit4] > at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:237)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2> 460018 T1350 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 99846 T1349 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {range_facet_l=Pulsing41(freqCutoff=20 minBlockSize=50 maxBlockSize=128), text=MockVariableIntBlock(baseBlockSize=69), _version_=PostingsFormat(name=Asserting), rnd_b=Pulsing41(freqCutoff=16 minBlockSize=50 maxBlockSize=128), intDefault=PostingsFormat(name=Asserting), timestamp=Pulsing41(freqCutoff=20 minBlockSize=50 maxBlockSize=128), id=Pulsing41(freqCutoff=16 minBlockSize=50 maxBlockSize=128), a_t=Pulsing41(freqCutoff=20 minBlockSize=50 maxBlockSize=128), range_facet_sl=Pulsing41(freqCutoff=16 minBlockSize=50 maxBlockSize=128), range_facet_si=Pulsing41(freqCutoff=20 minBlockSize=50 maxBlockSize=128), other_tl1=PostingsFormat(name=Asserting), multiDefault=Pulsing41(freqCutoff=20 minBlockSize=50 maxBlockSize=128), a_si=PostingsFormat(name=Asserting)}, docValues:{timestamp=DocValuesFormat(name=Asserting)}, sim=RandomSimilarityProvider(queryNorm=false,coord=crazy): {}, locale=ar_AE, timezone=America/New_York
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic amd64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=8,threads=1,free=18276352,total=126681088
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestFastLRUCache, TestReversedWildcardFilterFactory, OverseerCollectionProcessorTest, SystemInfoHandlerTest, AlternateDirectoryTest, TestCoreContainer, MinimalSchemaTest, TestPluginEnable, TestSolrDeletionPolicy1, SearchHandlerTest, TestValueSourceCache, DateFieldTest, TestCopyFieldCollectionResource, TestSolrCoreProperties, TestSerializedLuceneMatchVersion, SliceStateUpdateTest, TestPseudoReturnFields, UnloadDistributedZkTest, DistributedTermsComponentTest, LegacyHTMLStripCharFilterTest, ShowFileRequestHandlerTest, ExternalFileFieldSortTest, TestPhraseSuggestions, SolrCoreTest, ZkControllerTest, TermVectorComponentTest, SchemaVersionSpecificBehaviorTest, ClusterStateUpdateTest, TestPHPSerializedResponseWriter, ScriptEngineTest, AutoCommitTest, MoreLikeThisHandlerTest, TestPerFieldSimilarity, DistributedSpellCheckComponentTest, QueryParsingTest, TestSolrQueryParserDefaultOperatorResource, TestJoin, PluginInfoTest, TestFieldTypeCollectionResource, TestShardHandlerFactory, QueryEqualityTest, TestDocSet, CircularListTest, LukeRequestHandlerTest, IndexSchemaTest, BinaryUpdateRequestHandlerTest, TestManagedSchemaFieldResource, TestFieldResource, JsonLoaderTest, TestSchemaNameResource, FileBasedSpellCheckerTest, AnalysisAfterCoreReloadTest, TestRealTimeGet, TestRemoteStreaming, CSVRequestHandlerTest, UUIDFieldTest, TestSolrDeletionPolicy2, WordBreakSolrSpellCheckerTest, TestSweetSpotSimilarityFactory, FieldMutatingUpdateProcessorTest, ZkCLITest, RecoveryZkTest, SuggesterTest, BasicFunctionalityTest, TestIBSimilarityFactory, SyncSliceTest]
[junit4:junit4] Completed on J0 in 100.40s, 1 test, 1 failure <<< FAILURES!
[...truncated 520 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:386: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:366: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:190: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:443: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1245: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:889: There were test failures: 312 suites, 1316 tests, 1 failure, 20 ignored (13 assumptions)
Total time: 38 minutes 31 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0_25 -XX:+UseCompressedOops -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure