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/22 18:41:37 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/jdk1.8.0-ea-b93) - Build #
6186 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/6186/
Java: 32bit/jdk1.8.0-ea-b93 -client -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:58103/kc_xec/ms/collection1lastClient and got 249 from http://127.0.0.1:37440/kc_xec/ms/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:58103/kc_xec/ms/collection1lastClient and got 249 from http://127.0.0.1:37440/kc_xec/ms/collection1
at __randomizedtesting.SeedInfo.seed([B223EA35C45506C4:33C5642DB30A66F8]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:491)
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 9583 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 387901 T1798 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /kc_xec/ms
[junit4:junit4] 2> 387905 T1798 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1371918536107
[junit4:junit4] 2> 387906 T1798 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 387906 T1799 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 388006 T1798 oasc.ZkTestServer.run start zk server on port:43707
[junit4:junit4] 2> 388007 T1798 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 388089 T1805 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@a1e0b0 name:ZooKeeperConnection Watcher:127.0.0.1:43707 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 388090 T1798 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 388090 T1798 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 388093 T1798 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 388094 T1807 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@661f94 name:ZooKeeperConnection Watcher:127.0.0.1:43707/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 388095 T1798 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 388095 T1798 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 388097 T1798 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 388098 T1798 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 388099 T1798 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 388102 T1798 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 388102 T1798 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 388105 T1798 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 388106 T1798 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 388108 T1798 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 388109 T1798 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 388110 T1798 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 388111 T1798 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 388112 T1798 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 388113 T1798 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 388114 T1798 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 388114 T1798 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 388116 T1798 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 388116 T1798 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 388118 T1798 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 388118 T1798 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 388120 T1798 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 388120 T1798 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 388184 T1798 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 388203 T1798 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:38230
[junit4:junit4] 2> 388204 T1798 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 388204 T1798 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 388205 T1798 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371918536324
[junit4:junit4] 2> 388205 T1798 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371918536324/solr.xml
[junit4:junit4] 2> 388205 T1798 oasc.CoreContainer.<init> New CoreContainer 14090473
[junit4:junit4] 2> 388206 T1798 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371918536324/'
[junit4:junit4] 2> 388206 T1798 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371918536324/'
[junit4:junit4] 2> 388260 T1798 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 388260 T1798 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 388260 T1798 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 388261 T1798 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 388261 T1798 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 388261 T1798 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 388262 T1798 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 388262 T1798 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 388262 T1798 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 388263 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 388265 T1798 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 388266 T1798 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43707/solr
[junit4:junit4] 2> 388266 T1798 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 388267 T1798 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 388269 T1818 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@65cfcc name:ZooKeeperConnection Watcher:127.0.0.1:43707 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 388269 T1798 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 388270 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 388273 T1798 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 388274 T1820 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10fda62 name:ZooKeeperConnection Watcher:127.0.0.1:43707/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 388274 T1798 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 388275 T1798 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 388277 T1798 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 388278 T1798 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 388279 T1798 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38230_kc_xec%2Fms
[junit4:junit4] 2> 388280 T1798 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38230_kc_xec%2Fms
[junit4:junit4] 2> 388282 T1798 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 388285 T1798 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 388287 T1798 oasc.Overseer.start Overseer (id=89910053182504963-127.0.0.1:38230_kc_xec%2Fms-n_0000000000) starting
[junit4:junit4] 2> 388288 T1798 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 388290 T1822 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 388291 T1798 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 388292 T1798 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 388293 T1798 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 388295 T1821 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 388297 T1823 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 388297 T1823 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 389797 T1821 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 389798 T1821 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38230/kc_xec/ms",
[junit4:junit4] 2> "node_name":"127.0.0.1:38230_kc_xec%2Fms",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1"}
[junit4:junit4] 2> 389798 T1821 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 389798 T1821 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 389801 T1820 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> 390299 T1823 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371918536324/collection1
[junit4:junit4] 2> 390300 T1823 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 390301 T1823 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 390301 T1823 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 390302 T1823 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371918536324/collection1/'
[junit4:junit4] 2> 390303 T1823 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1371918536324/collection1/lib/README' to classloader
[junit4:junit4] 2> 390303 T1823 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1371918536324/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 390353 T1823 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 390397 T1823 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 390398 T1823 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 390402 T1823 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 390830 T1823 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 390830 T1823 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 390831 T1823 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 390836 T1823 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 390839 T1823 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 390849 T1823 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 390851 T1823 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 390854 T1823 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 390855 T1823 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 390855 T1823 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 390855 T1823 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 390856 T1823 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 390856 T1823 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 390856 T1823 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 390857 T1823 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371918536324/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371918536107/control/data/
[junit4:junit4] 2> 390857 T1823 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@762233
[junit4:junit4] 2> 390857 T1823 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 390857 T1823 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/control/data
[junit4:junit4] 2> 390858 T1823 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371918536107/control/data/index/
[junit4:junit4] 2> 390858 T1823 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371918536107/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 390858 T1823 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/control/data/index
[junit4:junit4] 2> 391800 T1823 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@fc1f5b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 391801 T1823 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 391803 T1823 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 391803 T1823 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 391811 T1823 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 391812 T1823 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 391812 T1823 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 391812 T1823 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 391813 T1823 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 391813 T1823 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 391813 T1823 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 391816 T1823 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 391824 T1823 oass.SolrIndexSearcher.<init> Opening Searcher@cc079f main
[junit4:junit4] 2> 391825 T1823 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 391825 T1823 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 391830 T1823 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 391830 T1823 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38230/kc_xec/ms collection:control_collection shard:shard1
[junit4:junit4] 2> 391830 T1824 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@cc079f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 391838 T1823 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 391847 T1823 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 391855 T1823 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 391855 T1823 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 391855 T1823 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:38230/kc_xec/ms/collection1/
[junit4:junit4] 2> 391855 T1823 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 391855 T1823 oasc.SyncStrategy.syncToMe http://127.0.0.1:38230/kc_xec/ms/collection1/ has no replicas
[junit4:junit4] 2> 391856 T1823 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:38230/kc_xec/ms/collection1/
[junit4:junit4] 2> 391856 T1823 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 392805 T1821 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 392811 T1820 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> 392830 T1823 oasc.ZkController.register We are http://127.0.0.1:38230/kc_xec/ms/collection1/ and leader is http://127.0.0.1:38230/kc_xec/ms/collection1/
[junit4:junit4] 2> 392831 T1823 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38230/kc_xec/ms
[junit4:junit4] 2> 392831 T1823 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 392832 T1823 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 392832 T1823 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 392833 T1823 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 392835 T1798 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 392835 T1798 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 392835 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 392839 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 392845 T1798 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 392845 T1827 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1598491 name:ZooKeeperConnection Watcher:127.0.0.1:43707/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 392846 T1798 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 392847 T1798 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 392856 T1798 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 392952 T1798 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 392961 T1798 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:58103
[junit4:junit4] 2> 392962 T1798 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 392963 T1798 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 392963 T1798 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371918541058
[junit4:junit4] 2> 392964 T1798 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371918541058/solr.xml
[junit4:junit4] 2> 392964 T1798 oasc.CoreContainer.<init> New CoreContainer 16068420
[junit4:junit4] 2> 392965 T1798 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371918541058/'
[junit4:junit4] 2> 392965 T1798 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371918541058/'
[junit4:junit4] 2> 393047 T1798 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 393048 T1798 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 393049 T1798 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 393049 T1798 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 393050 T1798 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 393050 T1798 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 393051 T1798 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 393051 T1798 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 393051 T1798 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 393052 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 393057 T1798 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 393058 T1798 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43707/solr
[junit4:junit4] 2> 393058 T1798 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 393059 T1798 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 393060 T1838 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@129b651 name:ZooKeeperConnection Watcher:127.0.0.1:43707 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 393060 T1798 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 393070 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 393073 T1798 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 393074 T1840 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@61191d name:ZooKeeperConnection Watcher:127.0.0.1:43707/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 393074 T1798 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 393085 T1798 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 394097 T1798 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58103_kc_xec%2Fms
[junit4:junit4] 2> 394099 T1798 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58103_kc_xec%2Fms
[junit4:junit4] 2> 394100 T1820 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 394101 T1827 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 394101 T1840 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 394102 T1820 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 394107 T1841 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 394107 T1841 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 394315 T1821 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 394315 T1821 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38230/kc_xec/ms",
[junit4:junit4] 2> "node_name":"127.0.0.1:38230_kc_xec%2Fms",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1"}
[junit4:junit4] 2> 394317 T1821 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58103/kc_xec/ms",
[junit4:junit4] 2> "node_name":"127.0.0.1:58103_kc_xec%2Fms",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1"}
[junit4:junit4] 2> 394317 T1821 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 394318 T1821 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 394321 T1820 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> 394321 T1827 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> 394321 T1840 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> 395108 T1841 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371918541058/collection1
[junit4:junit4] 2> 395109 T1841 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 395109 T1841 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 395109 T1841 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 395110 T1841 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371918541058/collection1/'
[junit4:junit4] 2> 395111 T1841 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1371918541058/collection1/lib/README' to classloader
[junit4:junit4] 2> 395111 T1841 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1371918541058/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 395140 T1841 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 395186 T1841 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 395187 T1841 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 395194 T1841 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 395747 T1841 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 395747 T1841 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 395748 T1841 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 395757 T1841 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 395762 T1841 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 395772 T1841 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 395774 T1841 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 395778 T1841 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 395779 T1841 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 395779 T1841 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 395780 T1841 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 395783 T1841 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 395784 T1841 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 395784 T1841 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 395784 T1841 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371918541058/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/
[junit4:junit4] 2> 395785 T1841 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@762233
[junit4:junit4] 2> 395785 T1841 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 395786 T1841 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1
[junit4:junit4] 2> 395786 T1841 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index/
[junit4:junit4] 2> 395787 T1841 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 395787 T1841 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index
[junit4:junit4] 2> 395948 T1841 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 395949 T1841 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 395950 T1841 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 395951 T1841 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 395951 T1841 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 395952 T1841 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 395952 T1841 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 395952 T1841 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 395953 T1841 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 395953 T1841 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 395954 T1841 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 395955 T1841 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 395958 T1841 oass.SolrIndexSearcher.<init> Opening Searcher@1122f80 main
[junit4:junit4] 2> 395959 T1841 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 395959 T1841 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 395969 T1842 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1122f80 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 395971 T1841 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 395971 T1841 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58103/kc_xec/ms collection:collection1 shard:shard1
[junit4:junit4] 2> 395972 T1841 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 395978 T1841 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 395979 T1841 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 395980 T1841 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 395980 T1841 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58103/kc_xec/ms/collection1/
[junit4:junit4] 2> 395980 T1841 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 395980 T1841 oasc.SyncStrategy.syncToMe http://127.0.0.1:58103/kc_xec/ms/collection1/ has no replicas
[junit4:junit4] 2> 395980 T1841 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:58103/kc_xec/ms/collection1/
[junit4:junit4] 2> 395981 T1841 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 397327 T1821 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 397334 T1840 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> 397334 T1820 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> 397334 T1827 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> 397337 T1841 oasc.ZkController.register We are http://127.0.0.1:58103/kc_xec/ms/collection1/ and leader is http://127.0.0.1:58103/kc_xec/ms/collection1/
[junit4:junit4] 2> 397338 T1841 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58103/kc_xec/ms
[junit4:junit4] 2> 397338 T1841 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 397338 T1841 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 397338 T1841 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 397339 T1841 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 397340 T1798 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 397341 T1798 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 397341 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 397444 T1798 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 397446 T1798 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:34161
[junit4:junit4] 2> 397447 T1798 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 397448 T1798 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 397448 T1798 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371918545548
[junit4:junit4] 2> 397449 T1798 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371918545548/solr.xml
[junit4:junit4] 2> 397449 T1798 oasc.CoreContainer.<init> New CoreContainer 8047400
[junit4:junit4] 2> 397450 T1798 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371918545548/'
[junit4:junit4] 2> 397450 T1798 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371918545548/'
[junit4:junit4] 2> 397523 T1798 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 397524 T1798 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 397524 T1798 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 397524 T1798 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 397525 T1798 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 397525 T1798 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 397525 T1798 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 397526 T1798 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 397526 T1798 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 397526 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 397529 T1798 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 397530 T1798 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43707/solr
[junit4:junit4] 2> 397530 T1798 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 397531 T1798 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 397533 T1854 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e98a26 name:ZooKeeperConnection Watcher:127.0.0.1:43707 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 397533 T1798 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 397534 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 397537 T1798 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 397539 T1856 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@25ec07 name:ZooKeeperConnection Watcher:127.0.0.1:43707/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 397539 T1798 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 397541 T1798 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 398544 T1798 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34161_kc_xec%2Fms
[junit4:junit4] 2> 398545 T1798 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34161_kc_xec%2Fms
[junit4:junit4] 2> 398547 T1840 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> 398547 T1856 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 398547 T1820 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> 398547 T1827 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> 398548 T1840 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 398549 T1820 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 398550 T1827 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 398553 T1857 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 398553 T1857 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 398839 T1821 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 398839 T1821 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58103/kc_xec/ms",
[junit4:junit4] 2> "node_name":"127.0.0.1:58103_kc_xec%2Fms",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1"}
[junit4:junit4] 2> 398843 T1821 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34161/kc_xec/ms",
[junit4:junit4] 2> "node_name":"127.0.0.1:34161_kc_xec%2Fms",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1"}
[junit4:junit4] 2> 398843 T1821 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 398843 T1821 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 398846 T1820 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> 398846 T1840 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> 398846 T1856 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> 398846 T1827 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> 399554 T1857 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371918545548/collection1
[junit4:junit4] 2> 399555 T1857 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 399555 T1857 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 399556 T1857 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 399557 T1857 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371918545548/collection1/'
[junit4:junit4] 2> 399557 T1857 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1371918545548/collection1/lib/README' to classloader
[junit4:junit4] 2> 399557 T1857 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1371918545548/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 399596 T1857 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 399634 T1857 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 399635 T1857 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 399639 T1857 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 400118 T1857 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 400119 T1857 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 400120 T1857 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 400129 T1857 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 400133 T1857 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 400143 T1857 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 400152 T1857 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 400157 T1857 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 400158 T1857 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 400158 T1857 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 400158 T1857 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 400159 T1857 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 400160 T1857 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 400160 T1857 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 400160 T1857 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371918545548/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/
[junit4:junit4] 2> 400161 T1857 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@762233
[junit4:junit4] 2> 400161 T1857 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 400162 T1857 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2
[junit4:junit4] 2> 400162 T1857 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index/
[junit4:junit4] 2> 400162 T1857 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 400163 T1857 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index
[junit4:junit4] 2> 400167 T1857 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@cb42e5; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 400168 T1857 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 400170 T1857 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 400171 T1857 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 400171 T1857 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 400172 T1857 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 400173 T1857 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 400174 T1857 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 400174 T1857 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 400175 T1857 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 400175 T1857 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 400178 T1857 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 400182 T1857 oass.SolrIndexSearcher.<init> Opening Searcher@ddb0f5 main
[junit4:junit4] 2> 400183 T1857 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 400184 T1857 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 400189 T1858 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ddb0f5 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 400191 T1857 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 400191 T1857 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34161/kc_xec/ms collection:collection1 shard:shard1
[junit4:junit4] 2> 400194 T1857 oasc.ZkController.register We are http://127.0.0.1:34161/kc_xec/ms/collection1/ and leader is http://127.0.0.1:58103/kc_xec/ms/collection1/
[junit4:junit4] 2> 400194 T1857 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34161/kc_xec/ms
[junit4:junit4] 2> 400195 T1857 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 400195 T1857 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2082 name=collection1 org.apache.solr.core.SolrCore@62b891 url=http://127.0.0.1:34161/kc_xec/ms/collection1 node=127.0.0.1:34161_kc_xec%2Fms C2082_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:34161/kc_xec/ms, node_name=127.0.0.1:34161_kc_xec%2Fms, state=down, collection=collection1, core=collection1}
[junit4:junit4] 2> 400195 T1859 C2082 P34161 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 400195 T1857 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 400196 T1859 C2082 P34161 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 400196 T1859 C2082 P34161 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 400197 T1859 C2082 P34161 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 400197 T1798 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 400197 T1798 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 400197 T1859 C2082 P34161 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 400198 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 400202 T1833 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 400299 T1798 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 400301 T1798 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:37440
[junit4:junit4] 2> 400301 T1798 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 400302 T1798 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 400302 T1798 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371918548404
[junit4:junit4] 2> 400302 T1798 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371918548404/solr.xml
[junit4:junit4] 2> 400303 T1798 oasc.CoreContainer.<init> New CoreContainer 26125109
[junit4:junit4] 2> 400303 T1798 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371918548404/'
[junit4:junit4] 2> 400303 T1798 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371918548404/'
[junit4:junit4] 2> 400360 T1821 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 400361 T1821 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34161/kc_xec/ms",
[junit4:junit4] 2> "node_name":"127.0.0.1:34161_kc_xec%2Fms",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1"}
[junit4:junit4] 2> 400365 T1840 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> 400365 T1820 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> 400365 T1827 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> 400365 T1856 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> 400373 T1798 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 400373 T1798 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 400374 T1798 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 400374 T1798 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 400375 T1798 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 400375 T1798 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 400375 T1798 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 400376 T1798 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 400376 T1798 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 400376 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 400379 T1798 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 400380 T1798 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43707/solr
[junit4:junit4] 2> 400380 T1798 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 400381 T1798 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 400382 T1871 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1dc225c name:ZooKeeperConnection Watcher:127.0.0.1:43707 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 400383 T1798 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 400384 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 400387 T1798 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 400388 T1873 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4bdc06 name:ZooKeeperConnection Watcher:127.0.0.1:43707/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 400389 T1798 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 400391 T1798 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 401202 T1833 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 401203 T1833 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={version=2&checkLive=true&nodeName=127.0.0.1:34161_kc_xec%252Fms&wt=javabin&state=recovering&onlyIfLeader=true&coreNodeName=3&action=PREPRECOVERY&core=collection1} status=0 QTime=1001
[junit4:junit4] 2> 401393 T1798 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:37440_kc_xec%2Fms
[junit4:junit4] 2> 401395 T1798 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:37440_kc_xec%2Fms
[junit4:junit4] 2> 401397 T1820 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> 401397 T1840 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> 401397 T1856 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 401397 T1827 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 401397 T1873 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 401399 T1820 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 401398 T1827 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> 401397 T1856 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> 401399 T1840 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 401404 T1874 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 401405 T1874 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 401869 T1821 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 401870 T1821 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:37440/kc_xec/ms",
[junit4:junit4] 2> "node_name":"127.0.0.1:37440_kc_xec%2Fms",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1"}
[junit4:junit4] 2> 401870 T1821 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 401870 T1821 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 401873 T1873 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> 401874 T1827 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> 401874 T1840 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> 401874 T1856 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> 401873 T1820 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> 402406 T1874 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371918548404/collection1
[junit4:junit4] 2> 402406 T1874 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 402407 T1874 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 402407 T1874 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 402408 T1874 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371918548404/collection1/'
[junit4:junit4] 2> 402408 T1874 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1371918548404/collection1/lib/README' to classloader
[junit4:junit4] 2> 402409 T1874 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1371918548404/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 402443 T1874 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 402486 T1874 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 402488 T1874 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 402492 T1874 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 402944 T1874 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 402945 T1874 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 402945 T1874 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 402951 T1874 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 402954 T1874 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 402963 T1874 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 402966 T1874 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 402969 T1874 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 402969 T1874 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 402970 T1874 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 402970 T1874 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 402971 T1874 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 402971 T1874 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 402971 T1874 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 402971 T1874 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371918548404/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/
[junit4:junit4] 2> 402972 T1874 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@762233
[junit4:junit4] 2> 402972 T1874 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 402972 T1874 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3
[junit4:junit4] 2> 402973 T1874 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index/
[junit4:junit4] 2> 402973 T1874 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 402973 T1874 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index
[junit4:junit4] 2> 402980 T1874 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@fae842; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 402980 T1874 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 402982 T1874 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 402982 T1874 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 402983 T1874 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 402983 T1874 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 402984 T1874 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 402984 T1874 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 402984 T1874 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 402985 T1874 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 402985 T1874 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 402987 T1874 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 402990 T1874 oass.SolrIndexSearcher.<init> Opening Searcher@2d196e main
[junit4:junit4] 2> 402991 T1874 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 402991 T1874 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 402998 T1875 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2d196e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 403000 T1874 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 403000 T1874 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:37440/kc_xec/ms collection:collection1 shard:shard1
[junit4:junit4] 2> 403003 T1874 oasc.ZkController.register We are http://127.0.0.1:37440/kc_xec/ms/collection1/ and leader is http://127.0.0.1:58103/kc_xec/ms/collection1/
[junit4:junit4] 2> 403003 T1874 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:37440/kc_xec/ms
[junit4:junit4] 2> 403003 T1874 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 403003 T1874 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2083 name=collection1 org.apache.solr.core.SolrCore@1296bfd url=http://127.0.0.1:37440/kc_xec/ms/collection1 node=127.0.0.1:37440_kc_xec%2Fms C2083_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:37440/kc_xec/ms, node_name=127.0.0.1:37440_kc_xec%2Fms, state=down, collection=collection1, core=collection1}
[junit4:junit4] 2> 403004 T1876 C2083 P37440 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 403004 T1874 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 403004 T1876 C2083 P37440 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 403005 T1876 C2083 P37440 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 403005 T1876 C2083 P37440 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 403005 T1798 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 403005 T1798 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 403006 T1876 C2083 P37440 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 403006 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 403010 T1836 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 403080 T1798 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 403082 T1798 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:42296
[junit4:junit4] 2> 403082 T1798 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 403083 T1798 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 403083 T1798 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371918551211
[junit4:junit4] 2> 403083 T1798 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371918551211/solr.xml
[junit4:junit4] 2> 403084 T1798 oasc.CoreContainer.<init> New CoreContainer 7969699
[junit4:junit4] 2> 403084 T1798 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371918551211/'
[junit4:junit4] 2> 403084 T1798 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371918551211/'
[junit4:junit4] 2> 403144 T1798 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 403144 T1798 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 403144 T1798 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 403145 T1798 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 403145 T1798 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 403145 T1798 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 403146 T1798 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 403146 T1798 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 403146 T1798 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 403147 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 403150 T1798 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 403151 T1798 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:43707/solr
[junit4:junit4] 2> 403151 T1798 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 403152 T1798 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 403153 T1888 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1397237 name:ZooKeeperConnection Watcher:127.0.0.1:43707 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 403154 T1798 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 403155 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 403158 T1798 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 403159 T1890 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d0c2c4 name:ZooKeeperConnection Watcher:127.0.0.1:43707/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 403159 T1798 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 403161 T1798 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C2084 name=collection1 org.apache.solr.core.SolrCore@62b891 url=http://127.0.0.1:34161/kc_xec/ms/collection1 node=127.0.0.1:34161_kc_xec%2Fms C2084_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:34161/kc_xec/ms, node_name=127.0.0.1:34161_kc_xec%2Fms, state=recovering, shard=shard1, collection=collection1, core=collection1}
[junit4:junit4] 2> 403204 T1859 C2084 P34161 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:58103/kc_xec/ms/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 403204 T1859 C2084 P34161 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34161/kc_xec/ms START replicas=[http://127.0.0.1:58103/kc_xec/ms/collection1/] nUpdates=100
[junit4:junit4] 2> 403205 T1859 C2084 P34161 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 403205 T1859 C2084 P34161 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 403205 T1859 C2084 P34161 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 403205 T1859 C2084 P34161 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 403206 T1859 C2084 P34161 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 403206 T1859 C2084 P34161 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:58103/kc_xec/ms/collection1/. core=collection1
[junit4:junit4] 2> 403206 T1859 C2084 P34161 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2085 name=collection1 org.apache.solr.core.SolrCore@1592848 url=http://127.0.0.1:58103/kc_xec/ms/collection1 node=127.0.0.1:58103_kc_xec%2Fms C2085_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:58103/kc_xec/ms, node_name=127.0.0.1:58103_kc_xec%2Fms, state=active, shard=shard1, collection=collection1, core=collection1, leader=true}
[junit4:junit4] 2> 403216 T1834 C2085 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/get params={version=2&wt=javabin&qt=/get&distrib=false&getVersions=100} status=0 QTime=0
[junit4:junit4] 2> 403220 T1835 C2085 P58103 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 403221 T1835 C2085 P58103 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 403222 T1835 C2085 P58103 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 403228 T1835 C2085 P58103 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 403229 T1835 C2085 P58103 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 403230 T1835 C2085 P58103 oass.SolrIndexSearcher.<init> Opening Searcher@15c152f realtime
[junit4:junit4] 2> 403230 T1835 C2085 P58103 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 403230 T1835 C2085 P58103 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&commit=true&wt=javabin&commit_end_point=true&openSearcher=false&softCommit=false&waitSearcher=true} {commit=} 0 11
[junit4:junit4] 2> ASYNC NEW_CORE C2086 name=collection1 org.apache.solr.core.SolrCore@62b891 url=http://127.0.0.1:34161/kc_xec/ms/collection1 node=127.0.0.1:34161_kc_xec%2Fms C2086_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:34161/kc_xec/ms, node_name=127.0.0.1:34161_kc_xec%2Fms, state=recovering, shard=shard1, collection=collection1, core=collection1}
[junit4:junit4] 2> 403231 T1859 C2086 P34161 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 403231 T1859 C2086 P34161 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 403235 T1833 C2085 P58103 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 403236 T1833 C2085 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/replication params={version=2&wt=javabin&qt=/replication&command=indexversion} status=0 QTime=4
[junit4:junit4] 2> 403236 T1859 C2086 P34161 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 403236 T1859 C2086 P34161 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 403237 T1859 C2086 P34161 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 403239 T1835 C2085 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/replication params={version=2&generation=2&wt=javabin&qt=/replication&command=filelist} status=0 QTime=1
[junit4:junit4] 2> 403239 T1859 C2086 P34161 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 403240 T1859 C2086 P34161 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index.20130622142911442
[junit4:junit4] 2> 403240 T1859 C2086 P34161 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index.20130622142911442 lockFactory=org.apache.lucene.store.NativeFSLockFactory@175decd; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 403243 T1834 C2085 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/replication params={generation=2&wt=filestream&qt=/replication&file=segments_2&command=filecontent&checksum=true} status=0 QTime=0
[junit4:junit4] 2> 403244 T1859 C2086 P34161 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 403249 T1859 C2086 P34161 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 403249 T1859 C2086 P34161 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 403251 T1859 C2086 P34161 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@cb42e5; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@cb42e5; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 403251 T1859 C2086 P34161 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 403252 T1859 C2086 P34161 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 403253 T1859 C2086 P34161 oass.SolrIndexSearcher.<init> Opening Searcher@e4f8bf main
[junit4:junit4] 2> 403255 T1858 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e4f8bf main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 403256 T1859 C2086 P34161 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index.20130622142911442 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index.20130622142911442;done=true>>]
[junit4:junit4] 2> 403257 T1859 C2086 P34161 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index.20130622142911442
[junit4:junit4] 2> 403257 T1859 C2086 P34161 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index.20130622142911442
[junit4:junit4] 2> 403258 T1859 C2086 P34161 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 403258 T1859 C2086 P34161 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 403258 T1859 C2086 P34161 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 403259 T1859 C2086 P34161 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 403260 T1859 C2086 P34161 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 403378 T1821 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 403379 T1821 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:37440/kc_xec/ms",
[junit4:junit4] 2> "node_name":"127.0.0.1:37440_kc_xec%2Fms",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1"}
[junit4:junit4] 2> 403381 T1821 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34161/kc_xec/ms",
[junit4:junit4] 2> "node_name":"127.0.0.1:34161_kc_xec%2Fms",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1"}
[junit4:junit4] 2> 403399 T1873 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> 403399 T1840 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> 403399 T1820 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> 403399 T1890 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> 403399 T1827 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> 403399 T1856 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> 404010 T1836 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 404011 T1836 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={version=2&checkLive=true&nodeName=127.0.0.1:37440_kc_xec%252Fms&wt=javabin&state=recovering&onlyIfLeader=true&coreNodeName=4&action=PREPRECOVERY&core=collection1} status=0 QTime=1001
[junit4:junit4] 2> 404164 T1798 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:42296_kc_xec%2Fms
[junit4:junit4] 2> 404167 T1798 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:42296_kc_xec%2Fms
[junit4:junit4] 2> 404170 T1840 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 404171 T1820 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 404170 T1827 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 404170 T1873 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 404172 T1827 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> 404171 T1820 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> 404171 T1890 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 404173 T1890 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> 404171 T1840 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> 404171 T1856 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 404172 T1873 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> 404175 T1856 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> 404182 T1893 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 404183 T1893 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 404904 T1821 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 404905 T1821 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42296/kc_xec/ms",
[junit4:junit4] 2> "node_name":"127.0.0.1:42296_kc_xec%2Fms",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1"}
[junit4:junit4] 2> 404905 T1821 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 404905 T1821 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 404918 T1873 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> 404919 T1827 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> 404919 T1890 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> 404919 T1820 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> 404919 T1856 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> 404918 T1840 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> 405184 T1893 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371918551211/collection1
[junit4:junit4] 2> 405185 T1893 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 405186 T1893 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 405186 T1893 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 405187 T1893 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371918551211/collection1/'
[junit4:junit4] 2> 405188 T1893 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1371918551211/collection1/lib/README' to classloader
[junit4:junit4] 2> 405188 T1893 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1371918551211/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 405237 T1893 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 405282 T1893 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 405284 T1893 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 405288 T1893 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 405717 T1893 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 405718 T1893 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 405718 T1893 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 405724 T1893 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 405734 T1893 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 405744 T1893 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 405747 T1893 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 405750 T1893 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 405751 T1893 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 405751 T1893 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 405752 T1893 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 405752 T1893 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 405753 T1893 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 405753 T1893 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 405753 T1893 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371918551211/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/
[junit4:junit4] 2> 405753 T1893 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@762233
[junit4:junit4] 2> 405754 T1893 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 405754 T1893 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4
[junit4:junit4] 2> 405754 T1893 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index/
[junit4:junit4] 2> 405755 T1893 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 405755 T1893 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index
[junit4:junit4] 2> 405758 T1893 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1324015; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 405758 T1893 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 405760 T1893 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 405760 T1893 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 405761 T1893 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 405761 T1893 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 405762 T1893 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 405762 T1893 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 405762 T1893 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 405763 T1893 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 405763 T1893 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 405765 T1893 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 405767 T1893 oass.SolrIndexSearcher.<init> Opening Searcher@35c187 main
[junit4:junit4] 2> 405768 T1893 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 405768 T1893 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 405774 T1894 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@35c187 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 405776 T1893 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 405776 T1893 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:42296/kc_xec/ms collection:collection1 shard:shard1
[junit4:junit4] 2> 405778 T1893 oasc.ZkController.register We are http://127.0.0.1:42296/kc_xec/ms/collection1/ and leader is http://127.0.0.1:58103/kc_xec/ms/collection1/
[junit4:junit4] 2> 405778 T1893 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:42296/kc_xec/ms
[junit4:junit4] 2> 405779 T1893 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 405779 T1893 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2087 name=collection1 org.apache.solr.core.SolrCore@71aacf url=http://127.0.0.1:42296/kc_xec/ms/collection1 node=127.0.0.1:42296_kc_xec%2Fms C2087_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:42296/kc_xec/ms, node_name=127.0.0.1:42296_kc_xec%2Fms, state=down, collection=collection1, core=collection1}
[junit4:junit4] 2> 405779 T1895 C2087 P42296 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 405779 T1893 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 405780 T1895 C2087 P42296 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 405780 T1895 C2087 P42296 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 405780 T1895 C2087 P42296 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 405780 T1798 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 405781 T1798 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 405781 T1895 C2087 P42296 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 405781 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 405784 T1798 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 405785 T1836 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 405785 T1798 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 405785 T1798 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 405786 T1798 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C2088 name=collection1 org.apache.solr.core.SolrCore@1296bfd url=http://127.0.0.1:37440/kc_xec/ms/collection1 node=127.0.0.1:37440_kc_xec%2Fms C2088_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:37440/kc_xec/ms, node_name=127.0.0.1:37440_kc_xec%2Fms, state=recovering, shard=shard1, collection=collection1, core=collection1}
[junit4:junit4] 2> 406011 T1876 C2088 P37440 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:58103/kc_xec/ms/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 406012 T1876 C2088 P37440 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:37440/kc_xec/ms START replicas=[http://127.0.0.1:58103/kc_xec/ms/collection1/] nUpdates=100
[junit4:junit4] 2> 406012 T1876 C2088 P37440 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 406012 T1876 C2088 P37440 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 406012 T1876 C2088 P37440 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 406013 T1876 C2088 P37440 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 406013 T1876 C2088 P37440 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 406013 T1876 C2088 P37440 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:58103/kc_xec/ms/collection1/. core=collection1
[junit4:junit4] 2> 406013 T1876 C2088 P37440 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2089 name=collection1 org.apache.solr.core.SolrCore@1592848 url=http://127.0.0.1:58103/kc_xec/ms/collection1 node=127.0.0.1:58103_kc_xec%2Fms C2089_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:58103/kc_xec/ms, node_name=127.0.0.1:58103_kc_xec%2Fms, state=active, shard=shard1, collection=collection1, core=collection1, leader=true}
[junit4:junit4] 2> 406014 T1834 C2089 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/get params={version=2&wt=javabin&qt=/get&distrib=false&getVersions=100} status=0 QTime=0
[junit4:junit4] 2> 406017 T1833 C2089 P58103 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 406028 T1833 C2089 P58103 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 406029 T1833 C2089 P58103 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 406029 T1833 C2089 P58103 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 406030 T1833 C2089 P58103 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&commit=true&wt=javabin&commit_end_point=true&openSearcher=false&softCommit=false&waitSearcher=true} {commit=} 0 13
[junit4:junit4] 2> 406030 T1876 C2088 P37440 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 406031 T1876 C2088 P37440 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 406033 T1834 C2089 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/replication params={version=2&wt=javabin&qt=/replication&command=indexversion} status=0 QTime=1
[junit4:junit4] 2> 406033 T1876 C2088 P37440 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 406033 T1876 C2088 P37440 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 406034 T1876 C2088 P37440 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 406035 T1833 C2089 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/replication params={version=2&generation=3&wt=javabin&qt=/replication&command=filelist} status=0 QTime=0
[junit4:junit4] 2> 406036 T1876 C2088 P37440 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 406037 T1876 C2088 P37440 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index.20130622142914238
[junit4:junit4] 2> 406037 T1876 C2088 P37440 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index.20130622142914238 lockFactory=org.apache.lucene.store.NativeFSLockFactory@591fe4; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 406039 T1835 C2089 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/replication params={generation=3&wt=filestream&qt=/replication&file=segments_3&command=filecontent&checksum=true} status=0 QTime=0
[junit4:junit4] 2> 406041 T1876 C2088 P37440 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 406042 T1876 C2088 P37440 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 406043 T1876 C2088 P37440 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 406044 T1876 C2088 P37440 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@fae842; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@fae842; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 406044 T1876 C2088 P37440 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 406045 T1876 C2088 P37440 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 406045 T1876 C2088 P37440 oass.SolrIndexSearcher.<init> Opening Searcher@14a573 main
[junit4:junit4] 2> 406046 T1875 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@14a573 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 406047 T1876 C2088 P37440 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index.20130622142914238 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index.20130622142914238;done=true>>]
[junit4:junit4] 2> 406047 T1876 C2088 P37440 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index.20130622142914238
[junit4:junit4] 2> 406047 T1876 C2088 P37440 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index.20130622142914238
[junit4:junit4] 2> 406047 T1876 C2088 P37440 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 406047 T1876 C2088 P37440 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 406048 T1876 C2088 P37440 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 406048 T1876 C2088 P37440 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 406049 T1876 C2088 P37440 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 406424 T1821 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 406424 T1821 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42296/kc_xec/ms",
[junit4:junit4] 2> "node_name":"127.0.0.1:42296_kc_xec%2Fms",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1"}
[junit4:junit4] 2> 406428 T1821 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:37440/kc_xec/ms",
[junit4:junit4] 2> "node_name":"127.0.0.1:37440_kc_xec%2Fms",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1"}
[junit4:junit4] 2> 406449 T1820 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> 406449 T1840 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> 406449 T1890 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> 406449 T1856 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> 406449 T1873 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> 406449 T1827 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> 406785 T1836 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 406786 T1836 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={version=2&checkLive=true&nodeName=127.0.0.1:42296_kc_xec%252Fms&wt=javabin&state=recovering&onlyIfLeader=true&coreNodeName=5&action=PREPRECOVERY&core=collection1} status=0 QTime=1001
[junit4:junit4] 2> 406787 T1798 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 407789 T1798 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C2087_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:42296/kc_xec/ms, node_name=127.0.0.1:42296_kc_xec%2Fms, state=recovering, shard=shard1, collection=collection1, core=collection1}
[junit4:junit4] 2> 408787 T1895 C2087 P42296 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:58103/kc_xec/ms/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 408787 T1895 C2087 P42296 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:42296/kc_xec/ms START replicas=[http://127.0.0.1:58103/kc_xec/ms/collection1/] nUpdates=100
[junit4:junit4] 2> 408787 T1895 C2087 P42296 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 408788 T1895 C2087 P42296 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 408788 T1895 C2087 P42296 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 408788 T1895 C2087 P42296 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 408788 T1895 C2087 P42296 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 408788 T1895 C2087 P42296 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:58103/kc_xec/ms/collection1/. core=collection1
[junit4:junit4] 2> 408788 T1895 C2087 P42296 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 408789 T1835 C2089 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/get params={version=2&wt=javabin&qt=/get&distrib=false&getVersions=100} status=0 QTime=0
[junit4:junit4] 2> 408790 T1798 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 408792 T1834 C2089 P58103 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 408808 T1834 C2089 P58103 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 408809 T1834 C2089 P58103 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 408810 T1834 C2089 P58103 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 408810 T1834 C2089 P58103 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&commit=true&wt=javabin&commit_end_point=true&openSearcher=false&softCommit=false&waitSearcher=true} {commit=} 0 18
[junit4:junit4] 2> 408811 T1895 C2087 P42296 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 408811 T1895 C2087 P42296 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 408813 T1836 C2089 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/replication params={version=2&wt=javabin&qt=/replication&command=indexversion} status=0 QTime=0
[junit4:junit4] 2> 408814 T1895 C2087 P42296 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 408814 T1895 C2087 P42296 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 408814 T1895 C2087 P42296 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 408816 T1835 C2089 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/replication params={version=2&generation=4&wt=javabin&qt=/replication&command=filelist} status=0 QTime=0
[junit4:junit4] 2> 408817 T1895 C2087 P42296 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 408818 T1895 C2087 P42296 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index.20130622142917019
[junit4:junit4] 2> 408818 T1895 C2087 P42296 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index.20130622142917019 lockFactory=org.apache.lucene.store.NativeFSLockFactory@c286e6; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 408821 T1834 C2089 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/replication params={generation=4&wt=filestream&qt=/replication&file=segments_4&command=filecontent&checksum=true} status=0 QTime=0
[junit4:junit4] 2> 408822 T1895 C2087 P42296 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 408824 T1895 C2087 P42296 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 408824 T1895 C2087 P42296 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 408826 T1895 C2087 P42296 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1324015; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1324015; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 408826 T1895 C2087 P42296 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 408826 T1895 C2087 P42296 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 408827 T1895 C2087 P42296 oass.SolrIndexSearcher.<init> Opening Searcher@7eaa18 main
[junit4:junit4] 2> 408828 T1894 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7eaa18 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 408828 T1895 C2087 P42296 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index.20130622142917019 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index.20130622142917019;done=true>>]
[junit4:junit4] 2> 408829 T1895 C2087 P42296 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index.20130622142917019
[junit4:junit4] 2> 408829 T1895 C2087 P42296 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index.20130622142917019
[junit4:junit4] 2> 408829 T1895 C2087 P42296 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 408829 T1895 C2087 P42296 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 408830 T1895 C2087 P42296 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 408830 T1895 C2087 P42296 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 408831 T1895 C2087 P42296 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 409457 T1821 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 409458 T1821 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "base_url":"http://127.0.0.1:42296/kc_xec/ms",
[junit4:junit4] 2> "node_name":"127.0.0.1:42296_kc_xec%2Fms",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "numShards":"1"}
[junit4:junit4] 2> 409460 T1820 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> 409461 T1827 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> 409461 T1840 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> 409461 T1873 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> 409461 T1890 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> 409461 T1856 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> 409792 T1798 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 409793 T1798 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C2090 name=collection1 org.apache.solr.core.SolrCore@5981bf url=http://127.0.0.1:38230/kc_xec/ms/collection1 node=127.0.0.1:38230_kc_xec%2Fms C2090_STATE=coll:control_collection core:collection1 props:{base_url=http://127.0.0.1:38230/kc_xec/ms, node_name=127.0.0.1:38230_kc_xec%2Fms, state=active, shard=shard1, collection=control_collection, core=collection1, leader=true}
[junit4:junit4] 2> 409815 T1815 C2090 P38230 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 409819 T1815 C2090 P38230 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@fc1f5b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 409820 T1815 C2090 P38230 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 409848 T1815 C2090 P38230 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@fc1f5b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@fc1f5b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 409849 T1815 C2090 P38230 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 409850 T1815 C2090 P38230 oass.SolrIndexSearcher.<init> Opening Searcher@1c6b9fe main
[junit4:junit4] 2> 409851 T1815 C2090 P38230 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 409853 T1824 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1c6b9fe main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 409854 T1815 C2090 P38230 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&commit=true&wt=javabin&softCommit=false&waitSearcher=true} {commit=} 0 39
[junit4:junit4] 2> ASYNC NEW_CORE C2091 name=collection1 org.apache.solr.core.SolrCore@1592848 url=http://127.0.0.1:58103/kc_xec/ms/collection1 node=127.0.0.1:58103_kc_xec%2Fms C2091_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:58103/kc_xec/ms, node_name=127.0.0.1:58103_kc_xec%2Fms, state=active, shard=shard1, collection=collection1, core=collection1, leader=true}
[junit4:junit4] 2> 409861 T1834 C2091 P58103 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:58103/kc_xec/ms/collection1/, StdNode: http://127.0.0.1:34161/kc_xec/ms/collection1/, StdNode: http://127.0.0.1:37440/kc_xec/ms/collection1/, StdNode: http://127.0.0.1:42296/kc_xec/ms/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 409866 T1835 C2091 P58103 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C2092 name=collection1 org.apache.solr.core.SolrCore@62b891 url=http://127.0.0.1:34161/kc_xec/ms/collection1 node=127.0.0.1:34161_kc_xec%2Fms C2092_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:34161/kc_xec/ms, node_name=127.0.0.1:34161_kc_xec%2Fms, state=active, shard=shard1, collection=collection1, core=collection1}
[junit4:junit4] 2> 409878 T1850 C2092 P34161 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C2093 name=collection1 org.apache.solr.core.SolrCore@71aacf url=http://127.0.0.1:42296/kc_xec/ms/collection1 node=127.0.0.1:42296_kc_xec%2Fms C2093_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:42296/kc_xec/ms, node_name=127.0.0.1:42296_kc_xec%2Fms, state=active, shard=shard1, collection=collection1, core=collection1}
[junit4:junit4] 2> 409881 T1883 C2093 P42296 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C2094 name=collection1 org.apache.solr.core.SolrCore@1296bfd url=http://127.0.0.1:37440/kc_xec/ms/collection1 node=127.0.0.1:37440_kc_xec%2Fms C2094_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:37440/kc_xec/ms, node_name=127.0.0.1:37440_kc_xec%2Fms, state=active, shard=shard1, collection=collection1, core=collection1}
[junit4:junit4] 2> 409881 T1867 C2094 P37440 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 409888 T1835 C2091 P58103 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 409889 T1835 C2091 P58103 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 409889 T1835 C2091 P58103 oass.SolrIndexSearcher.<init> Opening Searcher@611f14 main
[junit4:junit4] 2> 409890 T1835 C2091 P58103 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 409891 T1842 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@611f14 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 409892 T1835 C2091 P58103 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&commit=true&wt=javabin&commit_end_point=true&expungeDeletes=false&softCommit=false&waitSearcher=true} {commit=} 0 26
[junit4:junit4] 2> 409918 T1867 C2094 P37440 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@fae842; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@fae842; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 409919 T1867 C2094 P37440 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 409920 T1867 C2094 P37440 oass.SolrIndexSearcher.<init> Opening Searcher@1e61bbd main
[junit4:junit4] 2> 409920 T1850 C2092 P34161 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@cb42e5; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@cb42e5; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 409920 T1867 C2094 P37440 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 409920 T1883 C2093 P42296 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1324015; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1324015; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 409921 T1883 C2093 P42296 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 409921 T1850 C2092 P34161 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 409922 T1875 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1e61bbd main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 409923 T1883 C2093 P42296 oass.SolrIndexSearcher.<init> Opening Searcher@1b414d9 main
[junit4:junit4] 2> 409923 T1850 C2092 P34161 oass.SolrIndexSearcher.<init> Opening Searcher@9fc9ec main
[junit4:junit4] 2> 409923 T1867 C2094 P37440 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&commit=true&wt=javabin&commit_end_point=true&expungeDeletes=false&softCommit=false&waitSearcher=true} {commit=} 0 42
[junit4:junit4] 2> 409923 T1883 C2093 P42296 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 409924 T1858 oasc.JmxMonitoredMap.put WARN Failed to register info bean: searcher javax.management.InstanceAlreadyExistsException: solr/collection1:id=org.apache.solr.search.SolrIndexSearcher,type=searcher
[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:513)
[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:298)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1846)
[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:1723)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[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> 409924 T1850 C2092 P34161 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 409925 T1894 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b414d9 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 409926 T1883 C2093 P42296 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&commit=true&wt=javabin&commit_end_point=true&expungeDeletes=false&softCommit=false&waitSearcher=true} {commit=} 0 45
[junit4:junit4] 2> 409926 T1858 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9fc9ec main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 409927 T1850 C2092 P34161 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&commit=true&wt=javabin&commit_end_point=true&expungeDeletes=false&softCommit=false&waitSearcher=true} {commit=} 0 49
[junit4:junit4] 2> 409928 T1834 C2091 P58103 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&commit=true&wt=javabin&softCommit=false&waitSearcher=true} {commit=} 0 67
[junit4:junit4] 2> 409928 T1798 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 409930 T1833 C2091 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/select params={version=2&rows=0&tests=checkShardConsistency&wt=javabin&distrib=false&q=*:*} hits=0 status=0 QTime=0
[junit4:junit4] 2> 409932 T1851 C2092 P34161 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/select params={version=2&rows=0&tests=checkShardConsistency&wt=javabin&distrib=false&q=*:*} hits=0 status=0 QTime=0
[junit4:junit4] 2> 409933 T1869 C2094 P37440 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/select params={version=2&rows=0&tests=checkShardConsistency&wt=javabin&distrib=false&q=*:*} hits=0 status=0 QTime=0
[junit4:junit4] 2> 409935 T1886 C2093 P42296 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/select params={version=2&rows=0&tests=checkShardConsistency&wt=javabin&distrib=false&q=*:*} hits=0 status=0 QTime=0
[junit4:junit4] 2> 411940 T1814 C2090 P38230 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin} {deleteByQuery=*:* (-1438560876117360640)} 0 2
[junit4:junit4] 2> 411950 T1851 C2092 P34161 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={update.from=http://127.0.0.1:58103/kc_xec/ms/collection1/&version=2&_version_=-1438560876125749248&wt=javabin&update.distrib=FROMLEADER} {deleteByQuery=*:* (-1438560876125749248)} 0 0
[junit4:junit4] 2> 411951 T1885 C2093 P42296 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={update.from=http://127.0.0.1:58103/kc_xec/ms/collection1/&version=2&_version_=-1438560876125749248&wt=javabin&update.distrib=FROMLEADER} {deleteByQuery=*:* (-1438560876125749248)} 0 1
[junit4:junit4] 2> 411951 T1869 C2094 P37440 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={update.from=http://127.0.0.1:58103/kc_xec/ms/collection1/&version=2&_version_=-1438560876125749248&wt=javabin&update.distrib=FROMLEADER} {deleteByQuery=*:* (-1438560876125749248)} 0 2
[junit4:junit4] 2> 411953 T1834 C2091 P58103 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&update.distrib=TOLEADER} {deleteByQuery=*:* (-1438560876125749248)} 0 7
[junit4:junit4] 2> 411954 T1850 C2092 P34161 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin} {deleteByQuery=*:*} 0 11
[junit4:junit4] 2> 411959 T1816 C2090 P38230 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin} {add=[0 (1438560876137283584)]} 0 2
[junit4:junit4] 2> 411974 T1868 C2094 P37440 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:58103/kc_xec/ms/collection1/} {add=[0 (1438560876146720768)]} 0 2
[junit4:junit4] 2> 411974 T1849 C2092 P34161 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:58103/kc_xec/ms/collection1/} {add=[0 (1438560876146720768)]} 0 2
[junit4:junit4] 2> 411975 T1886 C2093 P42296 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:58103/kc_xec/ms/collection1/} {add=[0 (1438560876146720768)]} 0 3
[junit4:junit4] 2> 411976 T1833 C2091 P58103 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:34161/kc_xec/ms/collection1/} {add=[0 (1438560876146720768)]} 0 10
[junit4:junit4] 2> 411977 T1852 C2092 P34161 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin} {add=[0]} 0 14
[junit4:junit4] 2> 411982 T1813 C2090 P38230 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin} {add=[1 (1438560876161400832)]} 0 2
[junit4:junit4] 2> 411993 T1851 C2092 P34161 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:58103/kc_xec/ms/collection1/} {add=[1 (1438560876168740864)]} 0 2
[junit4:junit4] 2> 411993 T1866 C2094 P37440 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:58103/kc_xec/ms/collection1/} {add=[1 (1438560876168740864)]} 0 2
[junit4:junit4] 2> 411994 T1883 C2093 P42296 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:58103/kc_xec/ms/collection1/} {add=[1 (1438560876168740864)]} 0 3
[junit4:junit4] 2> 411995 T1834 C2091 P58103 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:37440/kc_xec/ms/collection1/} {add=[1 (1438560876168740864)]} 0 8
[junit4:junit4] 2> 411996 T1867 C2094 P37440 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin} {add=[1]} 0 12
[junit4:junit4] 2> 412000 T1815 C2090 P38230 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin} {add=[2 (1438560876181323776)]} 0 1
[junit4:junit4] 2> 412006 T1833 C2091 P58103 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:34161/kc_xec/ms/collection1/]
[junit4:junit4] 2> 412007 T1833 C2091 P58103 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:34161/kc_xec/ms/collection1/ against:[http://127.0.0.1:34161/kc_xec/ms/collection1/] result:true
[junit4:junit4] 2> 412007 T1833 C2091 P58103 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:37440/kc_xec/ms/collection1/ against:[http://127.0.0.1:34161/kc_xec/ms/collection1/] result:false
[junit4:junit4] 2> 412008 T1833 C2091 P58103 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:42296/kc_xec/ms/collection1/ against:[http://127.0.0.1:34161/kc_xec/ms/collection1/] result:false
[junit4:junit4] 2> 412014 T1869 C2094 P37440 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:58103/kc_xec/ms/collection1/&test.distrib.skip.servers=http://127.0.0.1:34161/kc_xec/ms/collection1/} {add=[2 (1438560876191809536)]} 0 2
[junit4:junit4] 2> 412014 T1885 C2093 P42296 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:58103/kc_xec/ms/collection1/&test.distrib.skip.servers=http://127.0.0.1:34161/kc_xec/ms/collection1/} {add=[2 (1438560876191809536)]} 0 1
[junit4:junit4] 2> 412015 T1833 C2091 P58103 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:42296/kc_xec/ms/collection1/&test.distrib.skip.servers=http://127.0.0.1:34161/kc_xec/ms/collection1/} {add=[2 (1438560876191809536)]} 0 9
[junit4:junit4] 2> 412016 T1884 C2093 P42296 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&test.distrib.skip.servers=http://127.0.0.1:34161/kc_xec/ms/collection1/} {add=[2]} 0 13
[junit4:junit4] 2> 412022 T1814 C2090 P38230 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin} {add=[3 (1438560876203343872)]} 0 3
[junit4:junit4] 2> 412028 T1836 C2091 P58103 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:34161/kc_xec/ms/collection1/]
[junit4:junit4] 2> 412029 T1836 C2091 P58103 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:34161/kc_xec/ms/collection1/ against:[http://127.0.0.1:34161/kc_xec/ms/collection1/] result:true
[junit4:junit4] 2> 412030 T1836 C2091 P58103 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:37440/kc_xec/ms/collection1/ against:[http://127.0.0.1:34161/kc_xec/ms/collection1/] result:false
[junit4:junit4] 2> 412031 T1836 C2091 P58103 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:42296/kc_xec/ms/collection1/ against:[http://127.0.0.1:34161/kc_xec/ms/collection1/] result:false
[junit4:junit4] 2> 412037 T1886 C2093 P42296 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:58103/kc_xec/ms/collection1/&test.distrib.skip.servers=http://127.0.0.1:34161/kc_xec/ms/collection1/} {add=[3 (1438560876214878208)]} 0 1
[junit4:junit4] 2> 412038 T1868 C2094 P37440 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:58103/kc_xec/ms/collection1/&test.distrib.skip.servers=http://127.0.0.1:34161/kc_xec/ms/collection1/} {add=[3 (1438560876214878208)]} 0 2
[junit4:junit4] 2> 412039 T1836 C2091 P58103 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&update.distrib=TOLEADER&distrib.from=http://127.0.0.1:34161/kc_xec/ms/collection1/&test.distrib.skip.servers=http://127.0.0.1:34161/kc_xec/ms/collection1/} {add=[3 (1438560876214878208)]} 0 12
[junit4:junit4] 2> 412040 T1850 C2092 P34161 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&wt=javabin&test.distrib.skip.servers=http://127.0.0.1:34161/kc_xec/ms/collection1/&test.distrib.skip.servers=http://127.0.0.1:37440/kc_xec/ms/collection1/} {add=[3]} 0 15
[junit4:junit4] 2> 412043 T1816 C2090 P38230 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 412068 T1816 C2090 P38230 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@fc1f5b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@fc1f5b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 412069 T1816 C2090 P38230 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 412073 T1816 C2090 P38230 oass.SolrIndexSearcher.<init> Opening Searcher@1fd3342 main
[junit4:junit4] 2> 412074 T1816 C2090 P38230 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 412076 T1824 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1fd3342 main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):C4)}
[junit4:junit4] 2> 412077 T1816 C2090 P38230 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&commit=true&wt=javabin&softCommit=false&waitSearcher=true} {commit=} 0 34
[junit4:junit4] 2> 412081 T1883 C2093 P42296 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:58103/kc_xec/ms/collection1/, StdNode: http://127.0.0.1:34161/kc_xec/ms/collection1/, StdNode: http://127.0.0.1:37440/kc_xec/ms/collection1/, StdNode: http://127.0.0.1:42296/kc_xec/ms/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 412084 T1835 C2091 P58103 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 412084 T1852 C2092 P34161 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C2095 name=collection1 org.apache.solr.core.SolrCore@1296bfd url=http://127.0.0.1:37440/kc_xec/ms/collection1 node=127.0.0.1:37440_kc_xec%2Fms C2095_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:37440/kc_xec/ms, node_name=127.0.0.1:37440_kc_xec%2Fms, state=active, shard=shard1, collection=collection1, core=collection1}
[junit4:junit4] 2> 412085 T1867 C2095 P37440 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C2096 name=collection1 org.apache.solr.core.SolrCore@71aacf url=http://127.0.0.1:42296/kc_xec/ms/collection1 node=127.0.0.1:42296_kc_xec%2Fms C2096_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:42296/kc_xec/ms, node_name=127.0.0.1:42296_kc_xec%2Fms, state=active, shard=shard1, collection=collection1, core=collection1}
[junit4:junit4] 2> 412084 T1886 C2096 P42296 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C2097 name=collection1 org.apache.solr.core.SolrCore@1592848 url=http://127.0.0.1:58103/kc_xec/ms/collection1 node=127.0.0.1:58103_kc_xec%2Fms C2097_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:58103/kc_xec/ms, node_name=127.0.0.1:58103_kc_xec%2Fms, state=active, shard=shard1, collection=collection1, core=collection1, leader=true}
[junit4:junit4] 2> 412159 T1835 C2097 P58103 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=5
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@42f164; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 412160 T1835 C2097 P58103 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 412165 T1835 C2097 P58103 oass.SolrIndexSearcher.<init> Opening Searcher@8fd8bf main
[junit4:junit4] 2> 412166 T1835 C2097 P58103 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 412168 T1842 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@8fd8bf main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):C4)}
[junit4:junit4] 2> 412169 T1835 C2097 P58103 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&commit=true&wt=javabin&commit_end_point=true&expungeDeletes=false&softCommit=false&waitSearcher=true} {commit=} 0 85
[junit4:junit4] 2> 412179 T1867 C2095 P37440 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@fae842; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@fae842; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> ASYNC NEW_CORE C2098 name=collection1 org.apache.solr.core.SolrCore@62b891 url=http://127.0.0.1:34161/kc_xec/ms/collection1 node=127.0.0.1:34161_kc_xec%2Fms C2098_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:34161/kc_xec/ms, node_name=127.0.0.1:34161_kc_xec%2Fms, state=active, shard=shard1, collection=collection1, core=collection1}
[junit4:junit4] 2> 412179 T1852 C2098 P34161 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@cb42e5; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@cb42e5; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 412179 T1886 C2096 P42296 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1324015; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371918536107/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1324015; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 412182 T1886 C2096 P42296 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 412181 T1852 C2098 P34161 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 412180 T1867 C2095 P37440 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 412187 T1886 C2096 P42296 oass.SolrIndexSearcher.<init> Opening Searcher@e2a2c9 main
[junit4:junit4] 2> 412187 T1852 C2098 P34161 oass.SolrIndexSearcher.<init> Opening Searcher@15c5e3e main
[junit4:junit4] 2> 412188 T1867 C2095 P37440 oass.SolrIndexSearcher.<init> Opening Searcher@19bda62 main
[junit4:junit4] 2> 412188 T1886 C2096 P42296 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 412189 T1867 C2095 P37440 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 412189 T1858 oasc.JmxMonitoredMap.put WARN Failed to register info bean: searcher javax.management.InstanceAlreadyExistsException: solr/collection1:id=org.apache.solr.search.SolrIndexSearcher,type=searcher
[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:513)
[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:298)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1846)
[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:1723)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:262)
[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> 412192 T1875 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@19bda62 main{StandardDirectoryReader(segments_5:3:nrt _0(4.4):C4)}
[junit4:junit4] 2> 412189 T1852 C2098 P34161 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 412191 T1894 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e2a2c9 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):C4)}
[junit4:junit4] 2> 412194 T1867 C2095 P37440 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&commit=true&wt=javabin&commit_end_point=true&expungeDeletes=false&softCommit=false&waitSearcher=true} {commit=} 0 109
[junit4:junit4] 2> 412194 T1858 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@15c5e3e main{StandardDirectoryReader(segments_4:3:nrt _0(4.4):C2)}
[junit4:junit4] 2> 412195 T1886 C2096 P42296 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&commit=true&wt=javabin&commit_end_point=true&expungeDeletes=false&softCommit=false&waitSearcher=true} {commit=} 0 111
[junit4:junit4] 2> 412196 T1852 C2098 P34161 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&commit=true&wt=javabin&commit_end_point=true&expungeDeletes=false&softCommit=false&waitSearcher=true} {commit=} 0 112
[junit4:junit4] 2> 412197 T1883 C2096 P42296 oasup.LogUpdateProcessor.finish [collection1] webapp=/kc_xec/ms path=/update params={version=2&commit=true&wt=javabin&softCommit=false&waitSearcher=true} {commit=} 0 117
[junit4:junit4] 2> 412198 T1798 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 412199 T1798 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 412201 T1798 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 412204 T1834 C2097 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/select params={version=2&rows=0&tests=checkShardConsistency&wt=javabin&distrib=false&q=*:*} hits=4 status=0 QTime=1
[junit4:junit4] 2> 412207 T1851 C2098 P34161 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/select params={version=2&rows=0&tests=checkShardConsistency&wt=javabin&distrib=false&q=*:*} hits=2 status=0 QTime=0
[junit4:junit4] 2> 412210 T1869 C2095 P37440 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/select params={version=2&rows=0&tests=checkShardConsistency&wt=javabin&distrib=false&q=*:*} hits=4 status=0 QTime=0
[junit4:junit4] 2> 412213 T1885 C2096 P42296 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/select params={version=2&rows=0&tests=checkShardConsistency&wt=javabin&distrib=false&q=*:*} hits=4 status=0 QTime=0
[junit4:junit4] 2> 412214 T1798 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 412222 T1868 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : version=2&wt=javabin&shard=shard1&collection=collection1&action=SYNCSHARD
[junit4:junit4] 2> 412223 T1868 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 412229 T1833 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 412230 T1833 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:58103/kc_xec/ms/collection1/
[junit4:junit4] 2> 412231 T1833 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58103/kc_xec/ms START replicas=[http://127.0.0.1:34161/kc_xec/ms/collection1/, http://127.0.0.1:37440/kc_xec/ms/collection1/, http://127.0.0.1:42296/kc_xec/ms/collection1/] nUpdates=100
[junit4:junit4] 2> 412234 T1884 C2096 P42296 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/get params={version=2&wt=javabin&qt=/get&distrib=false&getVersions=100} status=0 QTime=0
[junit4:junit4] 2> 412235 T1866 C2095 P37440 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/get params={version=2&wt=javabin&qt=/get&distrib=false&getVersions=100} status=0 QTime=1
[junit4:junit4] 2> 412234 T1850 C2098 P34161 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/get params={version=2&wt=javabin&qt=/get&distrib=false&getVersions=100} status=0 QTime=0
[junit4:junit4] 2> 412235 T1833 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:58103/kc_xec/ms Received 5 versions from 127.0.0.1:42296/kc_xec/ms/collection1/
[junit4:junit4] 2> 412237 T1833 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:58103/kc_xec/ms Our versions are newer. ourLowThreshold=1438560876125749248 otherHigh=1438560876191809536
[junit4:junit4] 2> 412238 T1833 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:58103/kc_xec/ms Received 5 versions from 127.0.0.1:37440/kc_xec/ms/collection1/
[junit4:junit4] 2> 412238 T1833 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:58103/kc_xec/ms Our versions are newer. ourLowThreshold=1438560876125749248 otherHigh=1438560876191809536
[junit4:junit4] 2> 412239 T1833 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:58103/kc_xec/ms Received 3 versions from 127.0.0.1:34161/kc_xec/ms/collection1/
[junit4:junit4] 2> 412239 T1833 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:58103/kc_xec/ms Our versions are newer. ourLowThreshold=1438560876125749248 otherHigh=1438560876168740864
[junit4:junit4] 2> 412240 T1833 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58103/kc_xec/ms DONE. sync succeeded
[junit4:junit4] 2> 412240 T1833 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 412241 T1833 oasc.SyncStrategy.syncToMe http://127.0.0.1:58103/kc_xec/ms/collection1/: try and ask http://127.0.0.1:34161/kc_xec/ms/collection1/ to sync
[junit4:junit4] 2> 412242 T1833 oasc.SyncStrategy.syncToMe http://127.0.0.1:58103/kc_xec/ms/collection1/: try and ask http://127.0.0.1:37440/kc_xec/ms/collection1/ to sync
[junit4:junit4] 2> 412242 T1833 oasc.SyncStrategy.syncToMe http://127.0.0.1:58103/kc_xec/ms/collection1/: try and ask http://127.0.0.1:42296/kc_xec/ms/collection1/ to sync
[junit4:junit4] 2> 412243 T1849 C2098 P34161 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34161/kc_xec/ms START replicas=[http://127.0.0.1:58103/kc_xec/ms/collection1/] nUpdates=100
[junit4:junit4] 2> 412244 T1867 C2095 P37440 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:37440/kc_xec/ms START replicas=[http://127.0.0.1:58103/kc_xec/ms/collection1/] nUpdates=100
[junit4:junit4] 2> 412245 T1886 C2096 P42296 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:42296/kc_xec/ms START replicas=[http://127.0.0.1:58103/kc_xec/ms/collection1/] nUpdates=100
[junit4:junit4] 2> 412247 T1836 C2097 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/get params={version=2&wt=javabin&qt=/get&distrib=false&getVersions=100} status=0 QTime=1
[junit4:junit4] 2> 412248 T1835 C2097 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/get params={version=2&wt=javabin&qt=/get&distrib=false&getVersions=100} status=0 QTime=0
[junit4:junit4] 2> 412248 T1849 C2098 P34161 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:34161/kc_xec/ms Received 5 versions from 127.0.0.1:58103/kc_xec/ms/collection1/
[junit4:junit4] 2> 412249 T1836 C2097 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/get params={version=2&wt=javabin&qt=/get&distrib=false&getVersions=100} status=0 QTime=0
[junit4:junit4] 2> 412249 T1867 C2095 P37440 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:37440/kc_xec/ms Received 5 versions from 127.0.0.1:58103/kc_xec/ms/collection1/
[junit4:junit4] 2> 412250 T1886 C2096 P42296 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:42296/kc_xec/ms Received 5 versions from 127.0.0.1:58103/kc_xec/ms/collection1/
[junit4:junit4] 2> 412249 T1849 C2098 P34161 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:34161/kc_xec/ms Requesting updates from 127.0.0.1:58103/kc_xec/ms/collection1/n=2 versions=[1438560876214878208, 1438560876191809536]
[junit4:junit4] 2> 412251 T1886 C2096 P42296 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:42296/kc_xec/ms Our versions are newer. ourLowThreshold=1438560876125749248 otherHigh=1438560876191809536
[junit4:junit4] 2> 412252 T1886 C2096 P42296 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:42296/kc_xec/ms DONE. sync succeeded
[junit4:junit4] 2> 412250 T1867 C2095 P37440 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:37440/kc_xec/ms Our versions are newer. ourLowThreshold=1438560876125749248 otherHigh=1438560876191809536
[junit4:junit4] 2> 412253 T1886 C2096 P42296 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/get params={version=2&wt=javabin&qt=/get&distrib=false&sync=http://127.0.0.1:58103/kc_xec/ms/collection1/&getVersions=100} status=0 QTime=8
[junit4:junit4] 2> 412254 T1867 C2095 P37440 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:37440/kc_xec/ms DONE. sync succeeded
[junit4:junit4] 2> 412255 T1833 oasc.SyncStrategy.syncToMe http://127.0.0.1:58103/kc_xec/ms/collection1/: sync completed with http://127.0.0.1:42296/kc_xec/ms/collection1/
[junit4:junit4] 2> 412254 T1834 C2097 P58103 oasc.SolrCore.execute [collection1] webapp=/kc_xec/ms path=/get params={version=2&getUpdates=1438560876214878208,1438560876191809536&wt=javabin&qt=/get&dis
[...truncated too long message...]
1> "shard":"shard1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "core":"collection1"},
[junit4:junit4] 1> "3":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:34161/kc_xec/ms",
[junit4:junit4] 1> "node_name":"127.0.0.1:34161_kc_xec%2Fms",
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "core":"collection1"},
[junit4:junit4] 1> "4":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:37440/kc_xec/ms",
[junit4:junit4] 1> "node_name":"127.0.0.1:37440_kc_xec%2Fms",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "core":"collection1"},
[junit4:junit4] 1> "5":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:42296/kc_xec/ms",
[junit4:junit4] 1> "node_name":"127.0.0.1:42296_kc_xec%2Fms",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "core":"collection1",
[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":{"1":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:38230/kc_xec/ms",
[junit4:junit4] 1> "node_name":"127.0.0.1:38230_kc_xec%2Fms",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "leader":"true"}}}},
[junit4:junit4] 1> "router":"compositeId"}}
[junit4:junit4] 1> /solr/configs (1)
[junit4:junit4] 1> /solr/configs/conf1 (9)
[junit4:junit4] 1> /solr/configs/conf1/schema.xml (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/currency.xml (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/open-exchange-rates.json (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "disclaimer": "This data is not real, it was synthetically created to match currency.xml. It is modeled after the data format available from openexchangerates.org. See https://openexchangerates.org/documentation for details",
[junit4:junit4] 1> "license": "http://www.apache.org/licenses/LICENSE-2.0",
[junit4:junit4] 1> "timestamp": 1332070464,
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 1> "IMPORTANT NOTE": "In order for tests to work, this data must be kept in sync with ./currency.xml",
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 1> "base": "USD",
[junit4:junit4] 1> "rates": {
[junit4:junit4] 1> "USD": 1,
[junit4:junit4] 1> "JPY": 81.29,
[junit4:junit4] 1> "EUR": 2.5,
[junit4:junit4] 1> "GBP": 0.5,
[junit4:junit4] 1> "MXN": 2.0
[junit4:junit4] 1> }
[junit4:junit4] 1> }
[junit4:junit4] 1>
[junit4:junit4] 1> /solr/configs/conf1/synonyms.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/stopwords.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/solrconfig.xml (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/mapping-ISOLatin1Accent.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/old_synonyms.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/configs/conf1/protwords.txt (0)
[junit4:junit4] 1> DATA: ...supressed...
[junit4:junit4] 1> /solr/aliases.json (0)
[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=B223EA35C45506C4 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=es_HN -Dtests.timezone=America/Godthab -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 102s J0 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:58103/kc_xec/ms/collection1lastClient and got 249 from http://127.0.0.1:37440/kc_xec/ms/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([B223EA35C45506C4:33C5642DB30A66F8]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
[junit4:junit4] > at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2> 490345 T1798 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 102448 T1797 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 2> 490397 T1873 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 490397 T1873 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> 490397 T1873 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 491500 T1890 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 491500 T1890 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 491501 T1890 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene41, sim=DefaultSimilarity, locale=es_HN, timezone=America/Godthab
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=1,free=37674024,total=100462592
[junit4:junit4] 2> NOTE: All tests run in this JVM: [ZkCLITest, SpatialFilterTest, ResponseLogComponentTest, OverseerTest, TestBadConfig, TestManagedSchemaFieldResource, OverseerCollectionProcessorTest, SuggesterFSTTest, SystemInfoHandlerTest, SearchHandlerTest, BadComponentTest, TestSolrQueryParserResource, DocumentBuilderTest, SOLR749Test, ShardRoutingTest, TestFieldCollectionResource, DistributedTermsComponentTest, TestSolrCoreProperties, LegacyHTMLStripCharFilterTest, SolrInfoMBeanTest, DateFieldTest, TestCharFilters, QueryEqualityTest, ReturnFieldsTest, TestSort, ClusterStateUpdateTest, TestFastLRUCache, TestLFUCache, MBeansHandlerTest, TestSweetSpotSimilarityFactory, TestJoin, SliceStateUpdateTest, MoreLikeThisHandlerTest, AutoCommitTest, DistributedQueryElevationComponentTest, LeaderElectionTest, PrimitiveFieldTypeTest, BinaryUpdateRequestHandlerTest, TestValueSourceCache, FieldMutatingUpdateProcessorTest, SoftAutoCommitTest, PreAnalyzedFieldTest, TestFastWriter, TestPHPSerializedResponseWriter, PreAnalyzedUpdateProcessorTest, WordBreakSolrSpellCheckerTest, SynonymTokenizerTest, TestClassNameShortening, TestQueryUtils, TestSurroundQueryParser, SolrCoreTest, CoreAdminHandlerTest, TestPhraseSuggestions, TestStressVersions, PolyFieldTest, SolrIndexSplitterTest, TestConfig, UpdateRequestProcessorFactoryTest, PrimUtilsTest, TestSchemaResource, TermVectorComponentTest, TestFaceting, TermsComponentTest, SyncSliceTest]
[junit4:junit4] Completed on J0 in 103.74s, 1 test, 1 failure <<< FAILURES!
[...truncated 629 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:392: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:372: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1246: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:890: There were test failures: 298 suites, 1256 tests, 1 failure, 16 ignored (7 assumptions)
Total time: 38 minutes 52 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.8.0-ea-b93 -client -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure