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/25 10:40:02 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.8.0-ea-b93) - Build #
6301 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/6301/
Java: 32bit/jdk1.8.0-ea-b93 -client -XX:+UseParallelGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:41864/collection1lastClient and got 262 from http://127.0.0.1:56558/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:41864/collection1lastClient and got 262 from http://127.0.0.1:56558/collection1
at __randomizedtesting.SeedInfo.seed([174AA3521A2CF474:96AC2D4A6D739448]: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 9449 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 178820 T1199 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 178823 T1199 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1372148703702
[junit4:junit4] 2> 178824 T1199 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 178824 T1200 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 178924 T1199 oasc.ZkTestServer.run start zk server on port:55968
[junit4:junit4] 2> 178925 T1199 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 179031 T1206 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16b7e66 name:ZooKeeperConnection Watcher:127.0.0.1:55968 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 179031 T1199 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 179031 T1199 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 179035 T1199 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 179036 T1208 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1ac91bb name:ZooKeeperConnection Watcher:127.0.0.1:55968/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 179037 T1199 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 179037 T1199 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 179039 T1199 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 179042 T1199 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 179043 T1199 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 179045 T1199 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 179045 T1199 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 179048 T1199 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 179049 T1199 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 179051 T1199 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 179052 T1199 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 179053 T1199 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 179054 T1199 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 179055 T1199 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 179056 T1199 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 179058 T1199 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 179058 T1199 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 179060 T1199 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 179060 T1199 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 179062 T1199 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 179062 T1199 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 179064 T1199 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 179065 T1199 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 179140 T1199 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 179143 T1199 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:38411
[junit4:junit4] 2> 179144 T1199 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 179144 T1199 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 179144 T1199 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372148703945
[junit4:junit4] 2> 179145 T1199 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372148703945/solr.xml
[junit4:junit4] 2> 179145 T1199 oasc.CoreContainer.<init> New CoreContainer 20525308
[junit4:junit4] 2> 179145 T1199 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372148703945/'
[junit4:junit4] 2> 179146 T1199 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372148703945/'
[junit4:junit4] 2> 179196 T1199 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 179197 T1199 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 179197 T1199 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 179197 T1199 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 179198 T1199 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 179198 T1199 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 179198 T1199 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 179199 T1199 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 179199 T1199 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 179199 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 179202 T1199 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 179203 T1199 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55968/solr
[junit4:junit4] 2> 179203 T1199 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 179204 T1199 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 179205 T1219 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b0f2b2 name:ZooKeeperConnection Watcher:127.0.0.1:55968 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 179205 T1199 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 179207 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 179209 T1199 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 179210 T1221 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@736cfe name:ZooKeeperConnection Watcher:127.0.0.1:55968/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 179210 T1199 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 179212 T1199 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 179214 T1199 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 179216 T1199 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 179217 T1199 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38411_
[junit4:junit4] 2> 179218 T1199 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38411_
[junit4:junit4] 2> 179220 T1199 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 179223 T1199 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 179225 T1199 oasc.Overseer.start Overseer (id=89925137445945347-127.0.0.1:38411_-n_0000000000) starting
[junit4:junit4] 2> 179228 T1199 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 179231 T1223 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 179231 T1199 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 179233 T1199 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 179234 T1199 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 179236 T1222 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 179238 T1224 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 179238 T1224 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 180738 T1222 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 180739 T1222 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:38411_",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38411",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 180739 T1222 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 180740 T1222 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 180743 T1221 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> 181240 T1224 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372148703945/collection1
[junit4:junit4] 2> 181240 T1224 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 181241 T1224 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 181241 T1224 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 181242 T1224 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372148703945/collection1/'
[junit4:junit4] 2> 181243 T1224 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372148703945/collection1/lib/README' to classloader
[junit4:junit4] 2> 181243 T1224 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372148703945/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 181282 T1224 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 181326 T1224 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 181327 T1224 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 181331 T1224 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 181718 T1224 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 181725 T1224 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 181728 T1224 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 181741 T1224 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 181744 T1224 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 181747 T1224 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 181748 T1224 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 181748 T1224 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 181748 T1224 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 181749 T1224 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 181749 T1224 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 181749 T1224 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 181750 T1224 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372148703945/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372148703701/control/data/
[junit4:junit4] 2> 181750 T1224 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1904194
[junit4:junit4] 2> 181750 T1224 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 181751 T1224 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/control/data
[junit4:junit4] 2> 181751 T1224 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372148703701/control/data/index/
[junit4:junit4] 2> 181751 T1224 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372148703701/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 181752 T1224 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/control/data/index
[junit4:junit4] 2> 181756 T1224 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1446d3d; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 181757 T1224 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 181760 T1224 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 181760 T1224 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 181761 T1224 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 181762 T1224 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 181763 T1224 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 181763 T1224 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 181763 T1224 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 181764 T1224 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 181764 T1224 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 181766 T1224 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 181768 T1224 oass.SolrIndexSearcher.<init> Opening Searcher@194d5e5 main
[junit4:junit4] 2> 181769 T1224 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 181769 T1224 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 181775 T1225 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@194d5e5 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 181776 T1224 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 181776 T1224 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38411 collection:control_collection shard:shard1
[junit4:junit4] 2> 181777 T1224 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 181785 T1224 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 181789 T1224 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 181789 T1224 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 181790 T1224 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:38411/collection1/
[junit4:junit4] 2> 181790 T1224 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 181791 T1224 oasc.SyncStrategy.syncToMe http://127.0.0.1:38411/collection1/ has no replicas
[junit4:junit4] 2> 181791 T1224 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:38411/collection1/
[junit4:junit4] 2> 181792 T1224 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 182246 T1222 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 182253 T1221 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> 182301 T1224 oasc.ZkController.register We are http://127.0.0.1:38411/collection1/ and leader is http://127.0.0.1:38411/collection1/
[junit4:junit4] 2> 182301 T1224 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38411
[junit4:junit4] 2> 182301 T1224 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 182302 T1224 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 182302 T1224 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 182303 T1224 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 182304 T1199 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 182305 T1199 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 182305 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 182313 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 182318 T1199 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 182320 T1228 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f4d539 name:ZooKeeperConnection Watcher:127.0.0.1:55968/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 182320 T1199 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 182321 T1199 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 182325 T1199 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 182400 T1199 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 182402 T1199 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:41864
[junit4:junit4] 2> 182402 T1199 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 182402 T1199 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 182403 T1199 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372148707203
[junit4:junit4] 2> 182403 T1199 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372148707203/solr.xml
[junit4:junit4] 2> 182403 T1199 oasc.CoreContainer.<init> New CoreContainer 31231256
[junit4:junit4] 2> 182404 T1199 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372148707203/'
[junit4:junit4] 2> 182404 T1199 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372148707203/'
[junit4:junit4] 2> 182451 T1199 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 182452 T1199 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 182452 T1199 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 182452 T1199 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 182453 T1199 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 182453 T1199 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 182453 T1199 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 182454 T1199 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 182454 T1199 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 182454 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 182457 T1199 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 182457 T1199 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55968/solr
[junit4:junit4] 2> 182458 T1199 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 182458 T1199 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 182460 T1239 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@178fa5c name:ZooKeeperConnection Watcher:127.0.0.1:55968 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 182460 T1199 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 182461 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 182464 T1199 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 182465 T1241 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@193de23 name:ZooKeeperConnection Watcher:127.0.0.1:55968/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 182465 T1199 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 182469 T1199 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 183472 T1199 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41864_
[junit4:junit4] 2> 183474 T1199 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:41864_
[junit4:junit4] 2> 183479 T1221 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 183479 T1228 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 183480 T1221 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> 183479 T1241 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 183489 T1242 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 183489 T1242 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 183760 T1222 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 183761 T1222 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "node_name":"127.0.0.1:38411_",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38411",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 183766 T1222 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:41864_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41864",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 183766 T1222 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 183766 T1222 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 183771 T1228 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> 183771 T1241 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> 183771 T1221 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> 184491 T1242 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372148707203/collection1
[junit4:junit4] 2> 184492 T1242 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 184493 T1242 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 184493 T1242 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 184495 T1242 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372148707203/collection1/'
[junit4:junit4] 2> 184496 T1242 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372148707203/collection1/lib/README' to classloader
[junit4:junit4] 2> 184497 T1242 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372148707203/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 184530 T1242 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 184575 T1242 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 184577 T1242 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 184581 T1242 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 184981 T1242 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 184988 T1242 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 184991 T1242 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 185000 T1242 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 185003 T1242 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 185006 T1242 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 185006 T1242 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 185006 T1242 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 185007 T1242 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 185007 T1242 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 185007 T1242 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 185008 T1242 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 185008 T1242 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372148707203/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/
[junit4:junit4] 2> 185008 T1242 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1904194
[junit4:junit4] 2> 185009 T1242 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 185009 T1242 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1
[junit4:junit4] 2> 185009 T1242 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index/
[junit4:junit4] 2> 185009 T1242 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 185010 T1242 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index
[junit4:junit4] 2> 185012 T1242 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 185013 T1242 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 185014 T1242 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 185015 T1242 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 185015 T1242 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 185016 T1242 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 185016 T1242 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 185017 T1242 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 185017 T1242 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 185018 T1242 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 185018 T1242 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 185019 T1242 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 185023 T1242 oass.SolrIndexSearcher.<init> Opening Searcher@1ebd59f main
[junit4:junit4] 2> 185023 T1242 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 185023 T1242 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 185029 T1243 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ebd59f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 185031 T1242 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 185031 T1242 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:41864 collection:collection1 shard:shard1
[junit4:junit4] 2> 185032 T1242 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 185037 T1242 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 185038 T1242 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 185039 T1242 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 185039 T1242 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:41864/collection1/
[junit4:junit4] 2> 185039 T1242 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 185039 T1242 oasc.SyncStrategy.syncToMe http://127.0.0.1:41864/collection1/ has no replicas
[junit4:junit4] 2> 185039 T1242 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:41864/collection1/
[junit4:junit4] 2> 185040 T1242 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 185280 T1222 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 185285 T1228 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> 185285 T1221 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> 185285 T1241 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> 185294 T1242 oasc.ZkController.register We are http://127.0.0.1:41864/collection1/ and leader is http://127.0.0.1:41864/collection1/
[junit4:junit4] 2> 185294 T1242 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:41864
[junit4:junit4] 2> 185294 T1242 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 185294 T1242 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 185295 T1242 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 185296 T1242 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 185297 T1199 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 185297 T1199 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 185298 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 185373 T1199 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 185374 T1199 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:49279
[junit4:junit4] 2> 185375 T1199 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 185375 T1199 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 185375 T1199 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372148710178
[junit4:junit4] 2> 185376 T1199 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372148710178/solr.xml
[junit4:junit4] 2> 185376 T1199 oasc.CoreContainer.<init> New CoreContainer 702878
[junit4:junit4] 2> 185376 T1199 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372148710178/'
[junit4:junit4] 2> 185377 T1199 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372148710178/'
[junit4:junit4] 2> 185424 T1199 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 185424 T1199 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 185425 T1199 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 185425 T1199 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 185425 T1199 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 185426 T1199 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 185426 T1199 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 185426 T1199 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 185426 T1199 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 185427 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 185430 T1199 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 185430 T1199 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55968/solr
[junit4:junit4] 2> 185430 T1199 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 185431 T1199 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 185433 T1255 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@bca34b name:ZooKeeperConnection Watcher:127.0.0.1:55968 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 185433 T1199 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 185435 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 185438 T1199 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 185439 T1257 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c3798d name:ZooKeeperConnection Watcher:127.0.0.1:55968/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 185439 T1199 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 185443 T1199 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 186446 T1199 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49279_
[junit4:junit4] 2> 186448 T1199 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49279_
[junit4:junit4] 2> 186453 T1241 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> 186453 T1228 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> 186455 T1221 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 186455 T1221 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> 186456 T1257 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 186457 T1241 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 186457 T1228 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 186464 T1258 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 186464 T1258 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 186789 T1222 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 186790 T1222 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "node_name":"127.0.0.1:41864_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41864",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 186794 T1222 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:49279_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49279",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 186795 T1222 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 186795 T1222 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 186800 T1257 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> 186800 T1241 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> 186800 T1221 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> 186800 T1228 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> 187466 T1258 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372148710178/collection1
[junit4:junit4] 2> 187467 T1258 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 187468 T1258 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 187468 T1258 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 187470 T1258 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372148710178/collection1/'
[junit4:junit4] 2> 187472 T1258 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372148710178/collection1/lib/README' to classloader
[junit4:junit4] 2> 187473 T1258 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372148710178/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 187524 T1258 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 187570 T1258 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 187572 T1258 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 187576 T1258 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 187998 T1258 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 188008 T1258 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 188012 T1258 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 188023 T1258 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 188026 T1258 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 188028 T1258 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 188029 T1258 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 188029 T1258 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 188030 T1258 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 188030 T1258 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 188031 T1258 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 188031 T1258 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 188031 T1258 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372148710178/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/
[junit4:junit4] 2> 188031 T1258 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1904194
[junit4:junit4] 2> 188032 T1258 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 188032 T1258 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2
[junit4:junit4] 2> 188032 T1258 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index/
[junit4:junit4] 2> 188032 T1258 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 188033 T1258 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index
[junit4:junit4] 2> 188035 T1258 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1340fe; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 188036 T1258 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 188037 T1258 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 188038 T1258 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 188038 T1258 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 188039 T1258 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 188039 T1258 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 188039 T1258 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 188040 T1258 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 188040 T1258 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 188041 T1258 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 188042 T1258 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 188045 T1258 oass.SolrIndexSearcher.<init> Opening Searcher@13d0ebb main
[junit4:junit4] 2> 188046 T1258 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 188046 T1258 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 188052 T1259 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@13d0ebb main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 188054 T1258 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 188054 T1258 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49279 collection:collection1 shard:shard1
[junit4:junit4] 2> 188056 T1258 oasc.ZkController.register We are http://127.0.0.1:49279/collection1/ and leader is http://127.0.0.1:41864/collection1/
[junit4:junit4] 2> 188056 T1258 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49279
[junit4:junit4] 2> 188057 T1258 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 188057 T1258 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C350 name=collection1 org.apache.solr.core.SolrCore@193477 url=http://127.0.0.1:49279/collection1 node=127.0.0.1:49279_ C350_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:49279_, collection=collection1, state=down, core=collection1, base_url=http://127.0.0.1:49279}
[junit4:junit4] 2> 188060 T1260 C350 P49279 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 188061 T1258 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 188061 T1260 C350 P49279 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 188062 T1260 C350 P49279 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 188062 T1260 C350 P49279 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 188062 T1199 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 188063 T1199 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 188063 T1260 C350 P49279 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 188063 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 188069 T1235 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 188136 T1199 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 188137 T1199 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:56558
[junit4:junit4] 2> 188138 T1199 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 188138 T1199 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 188138 T1199 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372148712944
[junit4:junit4] 2> 188139 T1199 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372148712944/solr.xml
[junit4:junit4] 2> 188139 T1199 oasc.CoreContainer.<init> New CoreContainer 24688082
[junit4:junit4] 2> 188139 T1199 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372148712944/'
[junit4:junit4] 2> 188140 T1199 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372148712944/'
[junit4:junit4] 2> 188188 T1199 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 188188 T1199 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 188189 T1199 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 188189 T1199 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 188189 T1199 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 188190 T1199 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 188190 T1199 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 188190 T1199 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 188190 T1199 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 188191 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 188194 T1199 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 188194 T1199 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55968/solr
[junit4:junit4] 2> 188195 T1199 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 188195 T1199 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 188197 T1272 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7afae2 name:ZooKeeperConnection Watcher:127.0.0.1:55968 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 188197 T1199 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 188198 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 188201 T1199 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 188203 T1274 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15aa7 name:ZooKeeperConnection Watcher:127.0.0.1:55968/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 188203 T1199 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 188206 T1199 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 188306 T1222 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 188307 T1222 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:49279_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49279",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 188311 T1257 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> 188311 T1241 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> 188311 T1274 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> 188311 T1221 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> 188311 T1228 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> 189070 T1235 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 189070 T1235 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={checkLive=true&nodeName=127.0.0.1:49279_&wt=javabin&version=2&onlyIfLeader=true&state=recovering&core=collection1&coreNodeName=3&action=PREPRECOVERY} status=0 QTime=1001
[junit4:junit4] 2> 189209 T1199 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56558_
[junit4:junit4] 2> 189211 T1199 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:56558_
[junit4:junit4] 2> 189214 T1257 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> 189215 T1274 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 189215 T1241 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 189215 T1221 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 189216 T1241 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> 189216 T1228 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 189216 T1274 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> 189217 T1228 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> 189217 T1257 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 189216 T1221 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> 189221 T1275 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 189221 T1275 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 189815 T1222 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 189816 T1222 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:56558_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56558",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 189816 T1222 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 189817 T1222 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 189820 T1274 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> 189820 T1228 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> 189820 T1257 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> 189820 T1241 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> 189820 T1221 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> 190222 T1275 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372148712944/collection1
[junit4:junit4] 2> 190223 T1275 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 190224 T1275 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 190224 T1275 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 190225 T1275 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372148712944/collection1/'
[junit4:junit4] 2> 190226 T1275 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372148712944/collection1/lib/README' to classloader
[junit4:junit4] 2> 190226 T1275 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372148712944/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 190255 T1275 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 190292 T1275 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 190293 T1275 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 190297 T1275 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 190688 T1275 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 190696 T1275 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 190699 T1275 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 190711 T1275 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 190714 T1275 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 190717 T1275 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 190718 T1275 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 190718 T1275 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 190718 T1275 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 190719 T1275 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 190719 T1275 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 190720 T1275 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 190720 T1275 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372148712944/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/
[junit4:junit4] 2> 190720 T1275 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1904194
[junit4:junit4] 2> 190721 T1275 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 190721 T1275 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3
[junit4:junit4] 2> 190721 T1275 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index/
[junit4:junit4] 2> 190722 T1275 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 190722 T1275 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index
[junit4:junit4] 2> 190725 T1275 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@19c52d2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 190725 T1275 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 190727 T1275 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 190727 T1275 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 190728 T1275 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 190728 T1275 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 190729 T1275 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 190729 T1275 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 190729 T1275 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 190730 T1275 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 190730 T1275 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 190732 T1275 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 190735 T1275 oass.SolrIndexSearcher.<init> Opening Searcher@1934ba0 main
[junit4:junit4] 2> 190736 T1275 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 190736 T1275 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 190742 T1276 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1934ba0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 190744 T1275 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 190744 T1275 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:56558 collection:collection1 shard:shard1
[junit4:junit4] 2> 190747 T1275 oasc.ZkController.register We are http://127.0.0.1:56558/collection1/ and leader is http://127.0.0.1:41864/collection1/
[junit4:junit4] 2> 190747 T1275 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56558
[junit4:junit4] 2> 190748 T1275 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 190748 T1275 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C351 name=collection1 org.apache.solr.core.SolrCore@1a27c0a url=http://127.0.0.1:56558/collection1 node=127.0.0.1:56558_ C351_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:56558_, collection=collection1, state=down, core=collection1, base_url=http://127.0.0.1:56558}
[junit4:junit4] 2> 190748 T1277 C351 P56558 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 190749 T1275 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 190749 T1277 C351 P56558 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 190749 T1277 C351 P56558 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 190749 T1277 C351 P56558 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 190750 T1199 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 190750 T1199 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 190750 T1277 C351 P56558 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 190751 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 190755 T1234 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 190851 T1199 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 190852 T1199 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:35128
[junit4:junit4] 2> 190853 T1199 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 190853 T1199 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 190854 T1199 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372148715632
[junit4:junit4] 2> 190854 T1199 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372148715632/solr.xml
[junit4:junit4] 2> 190854 T1199 oasc.CoreContainer.<init> New CoreContainer 5221924
[junit4:junit4] 2> 190855 T1199 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372148715632/'
[junit4:junit4] 2> 190855 T1199 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372148715632/'
[junit4:junit4] 2> 190903 T1199 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 190903 T1199 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 190903 T1199 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 190904 T1199 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 190904 T1199 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 190904 T1199 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 190905 T1199 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 190905 T1199 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 190905 T1199 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 190906 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 190909 T1199 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 190909 T1199 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55968/solr
[junit4:junit4] 2> 190909 T1199 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 190910 T1199 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 190912 T1289 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f281a name:ZooKeeperConnection Watcher:127.0.0.1:55968 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 190912 T1199 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 190914 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 190917 T1199 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 190918 T1291 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1e7e068 name:ZooKeeperConnection Watcher:127.0.0.1:55968/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 190918 T1199 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 190921 T1199 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C352 name=collection1 org.apache.solr.core.SolrCore@193477 url=http://127.0.0.1:49279/collection1 node=127.0.0.1:49279_ C352_STATE=coll:collection1 core:collection1 props:{shard=shard1, node_name=127.0.0.1:49279_, collection=collection1, state=recovering, core=collection1, base_url=http://127.0.0.1:49279}
[junit4:junit4] 2> 191071 T1260 C352 P49279 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:41864/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 191075 T1260 C352 P49279 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 191078 T1260 C352 P49279 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49279 START replicas=[http://127.0.0.1:41864/collection1/] nUpdates=100
[junit4:junit4] 2> 191081 T1260 C352 P49279 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 191081 T1260 C352 P49279 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 191081 T1260 C352 P49279 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 191081 T1260 C352 P49279 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 191081 T1260 C352 P49279 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 191082 T1260 C352 P49279 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:41864/collection1/. core=collection1
[junit4:junit4] 2> 191082 T1260 C352 P49279 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C353 name=collection1 org.apache.solr.core.SolrCore@13edf60 url=http://127.0.0.1:41864/collection1 node=127.0.0.1:41864_ C353_STATE=coll:collection1 core:collection1 props:{shard=shard1, node_name=127.0.0.1:41864_, collection=collection1, state=active, core=collection1, base_url=http://127.0.0.1:41864, leader=true}
[junit4:junit4] 2> 191091 T1236 C353 P41864 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&qt=/get&version=2&getVersions=100&distrib=false} status=0 QTime=0
[junit4:junit4] 2> 191099 T1237 C353 P41864 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 191101 T1237 C353 P41864 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 191102 T1237 C353 P41864 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 191110 T1237 C353 P41864 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 191110 T1237 C353 P41864 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 191111 T1237 C353 P41864 oass.SolrIndexSearcher.<init> Opening Searcher@4226cb realtime
[junit4:junit4] 2> 191111 T1237 C353 P41864 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 191111 T1237 C353 P41864 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={openSearcher=false&commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2&commit_end_point=true} {commit=} 0 19
[junit4:junit4] 2> 191112 T1260 C352 P49279 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 191112 T1260 C352 P49279 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 191114 T1236 C353 P41864 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 191115 T1236 C353 P41864 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=2
[junit4:junit4] 2> 191115 T1260 C352 P49279 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 191115 T1260 C352 P49279 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 191116 T1260 C352 P49279 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 191117 T1237 C353 P41864 oasc.SolrCore.execute [collection1] webapp= path=/replication params={generation=2&qt=/replication&wt=javabin&version=2&command=filelist} status=0 QTime=0
[junit4:junit4] 2> 191118 T1260 C352 P49279 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 191118 T1260 C352 P49279 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index.20130625102515996
[junit4:junit4] 2> 191118 T1260 C352 P49279 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index.20130625102515996 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1b2c1; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 191121 T1235 C353 P41864 oasc.SolrCore.execute [collection1] webapp= path=/replication params={generation=2&file=segments_2&checksum=true&wt=filestream&qt=/replication&command=filecontent} status=0 QTime=1
[junit4:junit4] 2> 191122 T1260 C352 P49279 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 191130 T1260 C352 P49279 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 191131 T1260 C352 P49279 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 191132 T1260 C352 P49279 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1340fe; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1340fe; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 191132 T1260 C352 P49279 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 191133 T1260 C352 P49279 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 191133 T1260 C352 P49279 oass.SolrIndexSearcher.<init> Opening Searcher@1bd42aa main
[junit4:junit4] 2> 191134 T1259 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1bd42aa main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 191135 T1260 C352 P49279 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index.20130625102515996 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index.20130625102515996;done=true>>]
[junit4:junit4] 2> 191135 T1260 C352 P49279 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index.20130625102515996
[junit4:junit4] 2> 191135 T1260 C352 P49279 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index.20130625102515996
[junit4:junit4] 2> 191136 T1260 C352 P49279 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 191137 T1260 C352 P49279 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 191137 T1260 C352 P49279 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 191137 T1260 C352 P49279 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 191141 T1260 C352 P49279 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 191323 T1222 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 191324 T1222 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:56558_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56558",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 191326 T1222 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "node_name":"127.0.0.1:49279_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49279",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 191329 T1274 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> 191329 T1241 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> 191329 T1228 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> 191329 T1221 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> 191329 T1257 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> 191329 T1291 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> 191755 T1234 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 191756 T1234 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={checkLive=true&nodeName=127.0.0.1:56558_&wt=javabin&version=2&onlyIfLeader=true&state=recovering&core=collection1&coreNodeName=4&action=PREPRECOVERY} status=0 QTime=1001
[junit4:junit4] 2> 191924 T1199 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:35128_
[junit4:junit4] 2> 191926 T1199 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:35128_
[junit4:junit4] 2> 191928 T1241 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> 191928 T1221 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 191928 T1291 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 191928 T1221 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> 191928 T1228 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> 191928 T1274 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 191928 T1257 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 191928 T1291 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> 191929 T1257 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> 191929 T1274 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> 191930 T1241 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 191931 T1228 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 191935 T1294 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 191935 T1294 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 192833 T1222 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 192834 T1222 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:35128_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35128",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 192834 T1222 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 192834 T1222 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 192838 T1228 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> 192838 T1241 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> 192838 T1274 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> 192838 T1221 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> 192838 T1291 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> 192838 T1257 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> 192937 T1294 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372148715632/collection1
[junit4:junit4] 2> 192937 T1294 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 192938 T1294 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 192939 T1294 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 192940 T1294 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372148715632/collection1/'
[junit4:junit4] 2> 192941 T1294 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372148715632/collection1/lib/README' to classloader
[junit4:junit4] 2> 192942 T1294 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372148715632/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 192986 T1294 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 193025 T1294 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 193026 T1294 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 193031 T1294 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 193459 T1294 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 193467 T1294 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 193470 T1294 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 193486 T1294 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 193489 T1294 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 193492 T1294 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 193493 T1294 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 193493 T1294 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 193493 T1294 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 193494 T1294 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 193494 T1294 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 193495 T1294 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 193495 T1294 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372148715632/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/
[junit4:junit4] 2> 193495 T1294 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1904194
[junit4:junit4] 2> 193495 T1294 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 193496 T1294 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4
[junit4:junit4] 2> 193496 T1294 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index/
[junit4:junit4] 2> 193497 T1294 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 193497 T1294 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index
[junit4:junit4] 2> 193500 T1294 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@a33eec; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 193500 T1294 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 193502 T1294 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 193502 T1294 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 193503 T1294 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 193503 T1294 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 193504 T1294 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 193504 T1294 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 193504 T1294 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 193505 T1294 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 193505 T1294 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 193507 T1294 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 193510 T1294 oass.SolrIndexSearcher.<init> Opening Searcher@144cf main
[junit4:junit4] 2> 193510 T1294 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 193511 T1294 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 193516 T1295 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@144cf main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 193519 T1294 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 193519 T1294 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:35128 collection:collection1 shard:shard1
[junit4:junit4] 2> 193522 T1294 oasc.ZkController.register We are http://127.0.0.1:35128/collection1/ and leader is http://127.0.0.1:41864/collection1/
[junit4:junit4] 2> 193522 T1294 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:35128
[junit4:junit4] 2> 193522 T1294 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 193522 T1294 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C354 name=collection1 org.apache.solr.core.SolrCore@55f872 url=http://127.0.0.1:35128/collection1 node=127.0.0.1:35128_ C354_STATE=coll:collection1 core:collection1 props:{node_name=127.0.0.1:35128_, collection=collection1, state=down, core=collection1, base_url=http://127.0.0.1:35128}
[junit4:junit4] 2> 193523 T1296 C354 P35128 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 193523 T1294 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 193523 T1296 C354 P35128 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 193524 T1296 C354 P35128 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 193524 T1296 C354 P35128 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 193524 T1199 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 193525 T1199 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 193525 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 193529 T1296 C354 P35128 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 193529 T1199 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 193530 T1199 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 193530 T1199 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 193531 T1199 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 193532 T1237 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> ASYNC NEW_CORE C355 name=collection1 org.apache.solr.core.SolrCore@1a27c0a url=http://127.0.0.1:56558/collection1 node=127.0.0.1:56558_ C355_STATE=coll:collection1 core:collection1 props:{shard=shard1, node_name=127.0.0.1:56558_, collection=collection1, state=recovering, core=collection1, base_url=http://127.0.0.1:56558}
[junit4:junit4] 2> 193757 T1277 C355 P56558 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:41864/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 193757 T1277 C355 P56558 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56558 START replicas=[http://127.0.0.1:41864/collection1/] nUpdates=100
[junit4:junit4] 2> 193758 T1277 C355 P56558 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 193758 T1277 C355 P56558 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 193759 T1277 C355 P56558 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 193759 T1277 C355 P56558 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 193759 T1277 C355 P56558 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 193759 T1277 C355 P56558 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:41864/collection1/. core=collection1
[junit4:junit4] 2> 193759 T1277 C355 P56558 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C356 name=collection1 org.apache.solr.core.SolrCore@13edf60 url=http://127.0.0.1:41864/collection1 node=127.0.0.1:41864_ C356_STATE=coll:collection1 core:collection1 props:{shard=shard1, node_name=127.0.0.1:41864_, collection=collection1, state=active, core=collection1, base_url=http://127.0.0.1:41864, leader=true}
[junit4:junit4] 2> 193760 T1234 C356 P41864 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&qt=/get&version=2&getVersions=100&distrib=false} status=0 QTime=0
[junit4:junit4] 2> 193763 T1236 C356 P41864 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 193770 T1236 C356 P41864 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 193771 T1236 C356 P41864 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 193771 T1236 C356 P41864 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 193771 T1236 C356 P41864 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={openSearcher=false&commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2&commit_end_point=true} {commit=} 0 9
[junit4:junit4] 2> 193772 T1277 C355 P56558 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 193772 T1277 C355 P56558 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 193774 T1234 C356 P41864 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4:junit4] 2> 193774 T1277 C355 P56558 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 193775 T1277 C355 P56558 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 193775 T1277 C355 P56558 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 193776 T1236 C356 P41864 oasc.SolrCore.execute [collection1] webapp= path=/replication params={generation=3&qt=/replication&wt=javabin&version=2&command=filelist} status=0 QTime=0
[junit4:junit4] 2> 193777 T1277 C355 P56558 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 193778 T1277 C355 P56558 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index.20130625102518655
[junit4:junit4] 2> 193778 T1277 C355 P56558 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index.20130625102518655 lockFactory=org.apache.lucene.store.NativeFSLockFactory@551683; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 193780 T1235 C356 P41864 oasc.SolrCore.execute [collection1] webapp= path=/replication params={generation=3&file=segments_3&checksum=true&wt=filestream&qt=/replication&command=filecontent} status=0 QTime=0
[junit4:junit4] 2> 193781 T1277 C355 P56558 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 193783 T1277 C355 P56558 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 193783 T1277 C355 P56558 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 193785 T1277 C355 P56558 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@19c52d2; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@19c52d2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 193786 T1277 C355 P56558 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 193786 T1277 C355 P56558 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 193786 T1277 C355 P56558 oass.SolrIndexSearcher.<init> Opening Searcher@1c2a9b2 main
[junit4:junit4] 2> 193787 T1276 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1c2a9b2 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 193788 T1277 C355 P56558 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index.20130625102518655 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index.20130625102518655;done=true>>]
[junit4:junit4] 2> 193788 T1277 C355 P56558 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index.20130625102518655
[junit4:junit4] 2> 193788 T1277 C355 P56558 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index.20130625102518655
[junit4:junit4] 2> 193789 T1277 C355 P56558 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 193789 T1277 C355 P56558 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 193789 T1277 C355 P56558 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 193789 T1277 C355 P56558 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 193790 T1277 C355 P56558 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 194343 T1222 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 194345 T1222 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:35128_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35128",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 194351 T1222 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "node_name":"127.0.0.1:56558_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56558",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 194356 T1257 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> 194356 T1221 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> 194356 T1241 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> 194356 T1274 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> 194356 T1291 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> 194356 T1228 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> 194532 T1237 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 194533 T1199 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 194533 T1237 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={checkLive=true&nodeName=127.0.0.1:35128_&wt=javabin&version=2&onlyIfLeader=true&state=recovering&core=collection1&coreNodeName=5&action=PREPRECOVERY} status=0 QTime=1001
[junit4:junit4] 2> 195536 T1199 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C354_STATE=coll:collection1 core:collection1 props:{shard=shard1, node_name=127.0.0.1:35128_, collection=collection1, state=recovering, core=collection1, base_url=http://127.0.0.1:35128}
[junit4:junit4] 2> 196535 T1296 C354 P35128 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:41864/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 196535 T1296 C354 P35128 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:35128 START replicas=[http://127.0.0.1:41864/collection1/] nUpdates=100
[junit4:junit4] 2> 196536 T1296 C354 P35128 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 196536 T1296 C354 P35128 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 196537 T1296 C354 P35128 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 196537 T1296 C354 P35128 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 196537 T1296 C354 P35128 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 196538 T1296 C354 P35128 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:41864/collection1/. core=collection1
[junit4:junit4] 2> 196538 T1296 C354 P35128 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 196538 T1199 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 196538 T1235 C356 P41864 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&qt=/get&version=2&getVersions=100&distrib=false} status=0 QTime=0
[junit4:junit4] 2> 196545 T1234 C356 P41864 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 196560 T1234 C356 P41864 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 196561 T1234 C356 P41864 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 196562 T1234 C356 P41864 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 196562 T1234 C356 P41864 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={openSearcher=false&commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2&commit_end_point=true} {commit=} 0 17
[junit4:junit4] 2> 196563 T1296 C354 P35128 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 196564 T1296 C354 P35128 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 196566 T1237 C356 P41864 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&wt=javabin&version=2&command=indexversion} status=0 QTime=0
[junit4:junit4] 2> 196567 T1296 C354 P35128 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 196567 T1296 C354 P35128 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 196568 T1296 C354 P35128 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 196570 T1235 C356 P41864 oasc.SolrCore.execute [collection1] webapp= path=/replication params={generation=4&qt=/replication&wt=javabin&version=2&command=filelist} status=0 QTime=1
[junit4:junit4] 2> 196571 T1296 C354 P35128 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 196573 T1296 C354 P35128 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index.20130625102521450
[junit4:junit4] 2> 196573 T1296 C354 P35128 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index.20130625102521450 lockFactory=org.apache.lucene.store.NativeFSLockFactory@193fb39; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 196576 T1234 C356 P41864 oasc.SolrCore.execute [collection1] webapp= path=/replication params={generation=4&file=segments_4&checksum=true&wt=filestream&qt=/replication&command=filecontent} status=0 QTime=0
[junit4:junit4] 2> 196578 T1296 C354 P35128 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 196581 T1296 C354 P35128 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 196581 T1296 C354 P35128 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 196584 T1296 C354 P35128 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@a33eec; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@a33eec; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 196585 T1296 C354 P35128 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 196585 T1296 C354 P35128 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 196586 T1296 C354 P35128 oass.SolrIndexSearcher.<init> Opening Searcher@13df5a main
[junit4:junit4] 2> 196588 T1295 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@13df5a main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 196589 T1296 C354 P35128 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index.20130625102521450 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index.20130625102521450;done=true>>]
[junit4:junit4] 2> 196590 T1296 C354 P35128 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index.20130625102521450
[junit4:junit4] 2> 196590 T1296 C354 P35128 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index.20130625102521450
[junit4:junit4] 2> 196591 T1296 C354 P35128 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 196592 T1296 C354 P35128 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 196592 T1296 C354 P35128 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 196592 T1296 C354 P35128 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 196594 T1296 C354 P35128 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 197366 T1222 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 197367 T1222 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "node_name":"127.0.0.1:35128_",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:35128",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "operation":"state"}
[junit4:junit4] 2> 197372 T1274 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> 197372 T1221 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> 197372 T1257 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> 197372 T1291 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> 197372 T1228 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> 197372 T1241 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> 197541 T1199 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 197542 T1199 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C357 name=collection1 org.apache.solr.core.SolrCore@796a3a url=http://127.0.0.1:38411/collection1 node=127.0.0.1:38411_ C357_STATE=coll:control_collection core:collection1 props:{shard=shard1, node_name=127.0.0.1:38411_, collection=control_collection, state=active, core=collection1, base_url=http://127.0.0.1:38411, leader=true}
[junit4:junit4] 2> 197547 T1216 C357 P38411 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 197550 T1216 C357 P38411 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1446d3d; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 197550 T1216 C357 P38411 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 197560 T1216 C357 P38411 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1446d3d; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1446d3d; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 197560 T1216 C357 P38411 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 197561 T1216 C357 P38411 oass.SolrIndexSearcher.<init> Opening Searcher@f159e2 main
[junit4:junit4] 2> 197562 T1216 C357 P38411 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 197563 T1225 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@f159e2 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 197564 T1216 C357 P38411 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2} {commit=} 0 17
[junit4:junit4] 2> C355_STATE=coll:collection1 core:collection1 props:{shard=shard1, node_name=127.0.0.1:56558_, collection=collection1, state=active, core=collection1, base_url=http://127.0.0.1:56558}
[junit4:junit4] 2> 197576 T1270 C355 P56558 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:41864/collection1/, StdNode: http://127.0.0.1:49279/collection1/, StdNode: http://127.0.0.1:56558/collection1/, StdNode: http://127.0.0.1:35128/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 197580 T1268 C355 P56558 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 197581 T1236 C356 P41864 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C354_STATE=coll:collection1 core:collection1 props:{shard=shard1, node_name=127.0.0.1:35128_, collection=collection1, state=active, core=collection1, base_url=http://127.0.0.1:35128}
[junit4:junit4] 2> 197585 T1286 C354 P35128 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C358 name=collection1 org.apache.solr.core.SolrCore@193477 url=http://127.0.0.1:49279/collection1 node=127.0.0.1:49279_ C358_STATE=coll:collection1 core:collection1 props:{shard=shard1, node_name=127.0.0.1:49279_, collection=collection1, state=active, core=collection1, base_url=http://127.0.0.1:49279}
[junit4:junit4] 2> 197585 T1252 C358 P49279 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 197600 T1268 C355 P56558 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@19c52d2; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@19c52d2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 197600 T1268 C355 P56558 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 197601 T1268 C355 P56558 oass.SolrIndexSearcher.<init> Opening Searcher@661211 main
[junit4:junit4] 2> 197602 T1268 C355 P56558 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 197603 T1276 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@661211 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 197604 T1268 C355 P56558 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2&commit_end_point=true} {commit=} 0 25
[junit4:junit4] 2> 197630 T1252 C358 P49279 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1340fe; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1340fe; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 197630 T1286 C354 P35128 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@a33eec; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@a33eec; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 197631 T1286 C354 P35128 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 197630 T1236 C356 P41864 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 197632 T1286 C354 P35128 oass.SolrIndexSearcher.<init> Opening Searcher@16ffc6c main
[junit4:junit4] 2> 197632 T1236 C356 P41864 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 197631 T1252 C358 P49279 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 197633 T1236 C356 P41864 oass.SolrIndexSearcher.<init> Opening Searcher@15ca409 main
[junit4:junit4] 2> 197633 T1286 C354 P35128 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 197634 T1252 C358 P49279 oass.SolrIndexSearcher.<init> Opening Searcher@1684682 main
[junit4:junit4] 2> 197634 T1295 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@16ffc6c main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 197635 T1243 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@15ca409 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 197635 T1236 C356 P41864 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 197635 T1286 C354 P35128 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2&commit_end_point=true} {commit=} 0 50
[junit4:junit4] 2> 197636 T1259 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1684682 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 197635 T1236 C356 P41864 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2&commit_end_point=true} {commit=} 0 54
[junit4:junit4] 2> 197636 T1252 C358 P49279 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 197637 T1252 C358 P49279 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2&commit_end_point=true} {commit=} 0 52
[junit4:junit4] 2> 197637 T1270 C355 P56558 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2} {commit=} 0 62
[junit4:junit4] 2> 197638 T1199 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 197640 T1237 C356 P41864 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&wt=javabin&version=2&rows=0&distrib=false&q=*:*} hits=0 status=0 QTime=0
[junit4:junit4] 2> 197641 T1253 C358 P49279 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&wt=javabin&version=2&rows=0&distrib=false&q=*:*} hits=0 status=0 QTime=0
[junit4:junit4] 2> 197643 T1269 C355 P56558 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&wt=javabin&version=2&rows=0&distrib=false&q=*:*} hits=0 status=0 QTime=0
[junit4:junit4] 2> 197644 T1287 C354 P35128 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&wt=javabin&version=2&rows=0&distrib=false&q=*:*} hits=0 status=0 QTime=0
[junit4:junit4] 2> 199648 T1216 C357 P38411 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438802220967526400)} 0 2
[junit4:junit4] 2> 199658 T1251 C358 P49279 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&wt=javabin&version=2&_version_=-1438802220974866432&update.from=http://127.0.0.1:41864/collection1/} {deleteByQuery=*:* (-1438802220974866432)} 0 1
[junit4:junit4] 2> 199658 T1286 C354 P35128 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&wt=javabin&version=2&_version_=-1438802220974866432&update.from=http://127.0.0.1:41864/collection1/} {deleteByQuery=*:* (-1438802220974866432)} 0 1
[junit4:junit4] 2> 199658 T1269 C355 P56558 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&wt=javabin&version=2&_version_=-1438802220974866432&update.from=http://127.0.0.1:41864/collection1/} {deleteByQuery=*:* (-1438802220974866432)} 0 1
[junit4:junit4] 2> 199659 T1236 C356 P41864 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438802220974866432)} 0 5
[junit4:junit4] 2> 199659 T1253 C358 P49279 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:*} 0 9
[junit4:junit4] 2> 199664 T1217 C357 P38411 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1438802220983255040)]} 0 3
[junit4:junit4] 2> 199674 T1287 C354 P35128 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&wt=javabin&version=2&distrib.from=http://127.0.0.1:41864/collection1/} {add=[0 (1438802220992692224)]} 0 1
[junit4:junit4] 2> 199675 T1268 C355 P56558 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&wt=javabin&version=2&distrib.from=http://127.0.0.1:41864/collection1/} {add=[0 (1438802220992692224)]} 0 2
[junit4:junit4] 2> 199675 T1252 C358 P49279 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&wt=javabin&version=2&distrib.from=http://127.0.0.1:41864/collection1/} {add=[0 (1438802220992692224)]} 0 2
[junit4:junit4] 2> 199676 T1237 C356 P41864 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2&distrib.from=http://127.0.0.1:56558/collection1/} {add=[0 (1438802220992692224)]} 0 5
[junit4:junit4] 2> 199676 T1267 C355 P56558 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0]} 0 10
[junit4:junit4] 2> 199679 T1214 C357 P38411 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1438802221000032256)]} 0 1
[junit4:junit4] 2> 199685 T1251 C358 P49279 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&wt=javabin&version=2&distrib.from=http://127.0.0.1:41864/collection1/} {add=[1 (1438802221004226560)]} 0 0
[junit4:junit4] 2> 199686 T1284 C354 P35128 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&wt=javabin&version=2&distrib.from=http://127.0.0.1:41864/collection1/} {add=[1 (1438802221004226560)]} 0 1
[junit4:junit4] 2> 199686 T1270 C355 P56558 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&wt=javabin&version=2&distrib.from=http://127.0.0.1:41864/collection1/} {add=[1 (1438802221004226560)]} 0 1
[junit4:junit4] 2> 199686 T1235 C356 P41864 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2&distrib.from=http://127.0.0.1:49279/collection1/} {add=[1 (1438802221004226560)]} 0 4
[junit4:junit4] 2> 199687 T1250 C358 P49279 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1]} 0 6
[junit4:junit4] 2> 199689 T1215 C357 P38411 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1438802221011566592)]} 0 0
[junit4:junit4] 2> 199691 T1236 C356 P41864 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:49279/collection1/]
[junit4:junit4] 2> 199691 T1236 C356 P41864 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:49279/collection1/ against:[http://127.0.0.1:49279/collection1/] result:true
[junit4:junit4] 2> 199691 T1236 C356 P41864 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:56558/collection1/ against:[http://127.0.0.1:49279/collection1/] result:false
[junit4:junit4] 2> 199692 T1236 C356 P41864 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:35128/collection1/ against:[http://127.0.0.1:49279/collection1/] result:false
[junit4:junit4] 2> 199695 T1269 C355 P56558 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:49279/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2&distrib.from=http://127.0.0.1:41864/collection1/} {add=[2 (1438802221014712320)]} 0 1
[junit4:junit4] 2> 199695 T1285 C354 P35128 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:49279/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2&distrib.from=http://127.0.0.1:41864/collection1/} {add=[2 (1438802221014712320)]} 0 1
[junit4:junit4] 2> 199696 T1236 C356 P41864 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:49279/collection1/&wt=javabin&version=2} {add=[2 (1438802221014712320)]} 0 5
[junit4:junit4] 2> 199699 T1216 C357 P38411 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1438802221021003776)]} 0 1
[junit4:junit4] 2> 199702 T1237 C356 P41864 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:49279/collection1/]
[junit4:junit4] 2> 199703 T1237 C356 P41864 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:49279/collection1/ against:[http://127.0.0.1:49279/collection1/] result:true
[junit4:junit4] 2> 199703 T1237 C356 P41864 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:56558/collection1/ against:[http://127.0.0.1:49279/collection1/] result:false
[junit4:junit4] 2> 199703 T1237 C356 P41864 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:35128/collection1/ against:[http://127.0.0.1:49279/collection1/] result:false
[junit4:junit4] 2> 199707 T1268 C355 P56558 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:49279/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2&distrib.from=http://127.0.0.1:41864/collection1/} {add=[3 (1438802221027295232)]} 0 1
[junit4:junit4] 2> 199707 T1287 C354 P35128 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:49279/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2&distrib.from=http://127.0.0.1:41864/collection1/} {add=[3 (1438802221027295232)]} 0 1
[junit4:junit4] 2> 199708 T1237 C356 P41864 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:49279/collection1/&update.distrib=TOLEADER&wt=javabin&version=2&distrib.from=http://127.0.0.1:35128/collection1/} {add=[3 (1438802221027295232)]} 0 6
[junit4:junit4] 2> 199708 T1286 C354 P35128 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:49279/collection1/&test.distrib.skip.servers=http://127.0.0.1:56558/collection1/&wt=javabin&version=2} {add=[3]} 0 8
[junit4:junit4] 2> 199710 T1217 C357 P38411 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 199730 T1217 C357 P38411 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1446d3d; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1446d3d; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 199731 T1217 C357 P38411 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 199733 T1217 C357 P38411 oass.SolrIndexSearcher.<init> Opening Searcher@1888c32 main
[junit4:junit4] 2> 199734 T1217 C357 P38411 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 199735 T1225 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1888c32 main{StandardDirectoryReader(segments_3:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 199735 T1217 C357 P38411 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2} {commit=} 0 25
[junit4:junit4] 2> 199738 T1235 C356 P41864 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:41864/collection1/, StdNode: http://127.0.0.1:49279/collection1/, StdNode: http://127.0.0.1:56558/collection1/, StdNode: http://127.0.0.1:35128/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 199739 T1234 C356 P41864 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 199740 T1253 C358 P49279 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 199740 T1284 C354 P35128 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 199740 T1267 C355 P56558 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 199760 T1234 C356 P41864 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 199761 T1234 C356 P41864 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 199762 T1234 C356 P41864 oass.SolrIndexSearcher.<init> Opening Searcher@dbd64c main
[junit4:junit4] 2> 199762 T1234 C356 P41864 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 199763 T1243 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@dbd64c main{StandardDirectoryReader(segments_6:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 199764 T1234 C356 P41864 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2&commit_end_point=true} {commit=} 0 25
[junit4:junit4] 2> 199790 T1253 C358 P49279 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1340fe; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1340fe; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 199791 T1253 C358 P49279 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 199790 T1267 C355 P56558 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@19c52d2; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@19c52d2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 199791 T1267 C355 P56558 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 199790 T1284 C354 P35128 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@a33eec; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@a33eec; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 199792 T1253 C358 P49279 oass.SolrIndexSearcher.<init> Opening Searcher@9f3d1d main
[junit4:junit4] 2> 199792 T1284 C354 P35128 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 199793 T1253 C358 P49279 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 199793 T1267 C355 P56558 oass.SolrIndexSearcher.<init> Opening Searcher@1db675 main
[junit4:junit4] 2> 199793 T1259 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9f3d1d main{StandardDirectoryReader(segments_4:3:nrt _0(5.0):c2)}
[junit4:junit4] 2> 199794 T1267 C355 P56558 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 199794 T1253 C358 P49279 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2&commit_end_point=true} {commit=} 0 54
[junit4:junit4] 2> 199795 T1276 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1db675 main{StandardDirectoryReader(segments_5:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 199794 T1284 C354 P35128 oass.SolrIndexSearcher.<init> Opening Searcher@89aa7f main
[junit4:junit4] 2> 199795 T1267 C355 P56558 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2&commit_end_point=true} {commit=} 0 55
[junit4:junit4] 2> 199795 T1284 C354 P35128 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 199796 T1295 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@89aa7f main{StandardDirectoryReader(segments_6:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 199797 T1284 C354 P35128 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2&commit_end_point=true} {commit=} 0 57
[junit4:junit4] 2> 199798 T1235 C356 P41864 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2} {commit=} 0 61
[junit4:junit4] 2> 199798 T1199 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 199799 T1199 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 199800 T1199 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 199803 T1236 C356 P41864 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&wt=javabin&version=2&rows=0&distrib=false&q=*:*} hits=4 status=0 QTime=1
[junit4:junit4] 2> 199805 T1252 C358 P49279 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&wt=javabin&version=2&rows=0&distrib=false&q=*:*} hits=2 status=0 QTime=1
[junit4:junit4] 2> 199806 T1270 C355 P56558 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&wt=javabin&version=2&rows=0&distrib=false&q=*:*} hits=4 status=0 QTime=0
[junit4:junit4] 2> 199808 T1285 C354 P35128 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&wt=javabin&version=2&rows=0&distrib=false&q=*:*} hits=4 status=0 QTime=0
[junit4:junit4] 2> 199810 T1199 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 199815 T1269 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&wt=javabin&version=2&collection=collection1&action=SYNCSHARD
[junit4:junit4] 2> 199815 T1269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 199818 T1237 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 199819 T1237 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:41864/collection1/
[junit4:junit4] 2> 199819 T1237 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:41864 START replicas=[http://127.0.0.1:49279/collection1/, http://127.0.0.1:56558/collection1/, http://127.0.0.1:35128/collection1/] nUpdates=100
[junit4:junit4] 2> 199824 T1250 C358 P49279 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&qt=/get&version=2&getVersions=100&distrib=false} status=0 QTime=4
[junit4:junit4] 2> 199824 T1268 C355 P56558 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&qt=/get&version=2&getVersions=100&distrib=false} status=0 QTime=4
[junit4:junit4] 2> 199825 T1237 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:41864 Received 3 versions from 127.0.0.1:49279/collection1/
[junit4:junit4] 2> 199824 T1286 C354 P35128 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&qt=/get&version=2&getVersions=100&distrib=false} status=0 QTime=3
[junit4:junit4] 2> 199825 T1237 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:41864 Our versions are newer. ourLowThreshold=1438802220974866432 otherHigh=1438802221004226560
[junit4:junit4] 2> 199826 T1237 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:41864 Received 5 versions from 127.0.0.1:56558/collection1/
[junit4:junit4] 2> 199826 T1237 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:41864 Our versions are newer. ourLowThreshold=1438802220974866432 otherHigh=1438802221014712320
[junit4:junit4] 2> 199826 T1237 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:41864 Received 5 versions from 127.0.0.1:35128/collection1/
[junit4:junit4] 2> 199827 T1237 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:41864 Our versions are newer. ourLowThreshold=1438802220974866432 otherHigh=1438802221014712320
[junit4:junit4] 2> 199827 T1237 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:41864 DONE. sync succeeded
[junit4:junit4] 2> 199827 T1237 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 199827 T1237 oasc.SyncStrategy.syncToMe http://127.0.0.1:41864/collection1/: try and ask http://127.0.0.1:49279/collection1/ to sync
[junit4:junit4] 2> 199828 T1237 oasc.SyncStrategy.syncToMe http://127.0.0.1:41864/collection1/: try and ask http://127.0.0.1:56558/collection1/ to sync
[junit4:junit4] 2> 199829 T1237 oasc.SyncStrategy.syncToMe http://127.0.0.1:41864/collection1/: try and ask http://127.0.0.1:35128/collection1/ to sync
[junit4:junit4] 2> 199829 T1253 C358 P49279 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49279 START replicas=[http://127.0.0.1:41864/collection1/] nUpdates=100
[junit4:junit4] 2> 199830 T1270 C355 P56558 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56558 START replicas=[http://127.0.0.1:41864/collection1/] nUpdates=100
[junit4:junit4] 2> 199831 T1284 C354 P35128 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:35128 START replicas=[http://127.0.0.1:41864/collection1/] nUpdates=100
[junit4:junit4] 2> 199831 T1234 C356 P41864 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&qt=/get&version=2&getVersions=100&distrib=false} status=0 QTime=0
[junit4:junit4] 2> 199832 T1235 C356 P41864 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&qt=/get&version=2&getVersions=100&distrib=false} status=0 QTime=1
[junit4:junit4] 2> 199832 T1270 C355 P56558 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:56558 Received 5 versions from 127.0.0.1:41864/collection1/
[junit4:junit4] 2> 199832 T1236 C356 P41864 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&qt=/get&version=2&getVersions=100&distrib=false} status=0 QTime=0
[junit4:junit4] 2> 199832 T1270 C355 P56558 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:56558 Our versions are newer. ourLowThreshold=1438802220974866432 otherHigh=1438802221014712320
[junit4:junit4] 2> 199832 T1253 C358 P49279 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:49279 Received 5 versions from 127.0.0.1:41864/collection1/
[junit4:junit4] 2> 199833 T1270 C355 P56558 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56558 DONE. sync succeeded
[junit4:junit4] 2> 199833 T1284 C354 P35128 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:35128 Received 5 versions from 127.0.0.1:41864/collection1/
[junit4:junit4] 2> 199833 T1270 C355 P56558 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:41864/collection1/&wt=javabin&qt=/get&version=2&getVersions=100&distrib=false} status=0 QTime=3
[junit4:junit4] 2> 199833 T1253 C358 P49279 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:49279 Requesting updates from 127.0.0.1:41864/collection1/n=2 versions=[1438802221027295232, 1438802221014712320]
[junit4:junit4] 2> 199834 T1237 oasc.SyncStrategy.syncToMe http://127.0.0.1:41864/collection1/: sync completed with http://127.0.0.1:56558/collection1/
[junit4:junit4] 2> 199834 T1284 C354 P35128 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:35128 Our versions are newer. ourLowThreshold=1438802220974866432 otherHigh=1438802221014712320
[junit4:junit4] 2> 199835 T1284 C354 P35128 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:35128 DONE. sync succeeded
[junit4:junit4] 2> 199835 T1284 C354 P35128 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:41864/collection1/&wt=javabin&qt=/get&version=2&getVersions=100&distrib=false} status=0 QTime=4
[junit4:junit4] 2> 199836 T1237 oasc.SyncStrategy.syncToMe http://127.0.0.1:41864/collection1/: sync completed with http://127.0.0.1:35128/collection1/
[junit4:junit4] 2> 199836 T1234 C356 P41864 oasc.SolrCore.execute [collection1] webapp= path=/get params={wt=javabin&qt=/get&version=2&distrib=false&getUpdates=1438802221027295232,1438802221014712320} status=0 QTime=0
[junit4:junit4] 2> 199839 T1253 C358 P49279 oasup.LogUpdateProcessor.finish [collection1] {add=[2 (1438802221014712320), 3 (1438802221027295232)]} 0 3
[junit4:junit4] 2> 199839 T1253 C358 P49279 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:49279 DONE. sync succeeded
[junit4:junit4] 2> 199839 T1253 C358 P49279 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:41864/collection1/&wt=javabin&qt=/get&version=2&getVersions=100&distrib=false} status=0 QTime=10
[junit4:junit4] 2> 199840 T1237 oasc.SyncStrategy.syncToMe http://127.0.0.1:41864/collection1/: sync completed with http://127.0.0.1:49279/collection1/
[junit4:junit4] 2> 199840 T1237 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={shard=shard1&wt=javabin&version=2&collection=collection1&core=collection1&action=REQUESTSYNCSHARD} status=0 QTime=22
[junit4:junit4] 2> 199840 T1269 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/collections params={shard=shard1&wt=javabin&version=2&collection=collection1&action=SYNCSHARD} status=0 QTime=26
[junit4:junit4] 2> 199841 T1199 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 199841 T1199 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 199842 T1199 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 199843 T1199 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 199844 T1214 C357 P38411 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 199890 T1214 C357 P38411 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1446d3d; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1446d3d; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 199890 T1214 C357 P38411 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 199891 T1214 C357 P38411 oass.SolrIndexSearcher.<init> Opening Searcher@6b4093 main
[junit4:junit4] 2> 199891 T1214 C357 P38411 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 199892 T1225 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6b4093 main{StandardDirectoryReader(segments_3:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 199893 T1214 C357 P38411 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2} {commit=} 0 49
[junit4:junit4] 2> 199895 T1252 C358 P49279 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:41864/collection1/, StdNode: http://127.0.0.1:49279/collection1/, StdNode: http://127.0.0.1:56558/collection1/, StdNode: http://127.0.0.1:35128/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 199897 T1268 C355 P56558 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 199897 T1285 C354 P35128 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 199897 T1235 C356 P41864 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 199897 T1251 C358 P49279 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 199920 T1268 C355 P56558 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@19c52d2; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@19c52d2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 199921 T1268 C355 P56558 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 199921 T1268 C355 P56558 oass.SolrIndexSearcher.<init> Opening Searcher@964fe9 main
[junit4:junit4] 2> 199922 T1268 C355 P56558 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 199923 T1276 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@964fe9 main{StandardDirectoryReader(segments_5:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 199923 T1268 C355 P56558 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={expungeDeletes=false&commit=true&wt=javabin&waitSearcher=true&softCommit=false&version=2&commit_end_point=true} {commit=} 0 26
[junit4:junit4] 2> 199940 T1285 C354 P35128 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@a33eec; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@a33eec; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_7,generation=7}
[junit4:junit4] 2> 199941 T1285 C354 P35128 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 7
[junit4:junit4] 2> 199940 T1235 C356 P41864 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; 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-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372148703701/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a9c4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_7,generation=7}
[junit4:junit4] 2> 199942 T1235 C356 P41864 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 7
[junit4:junit4] 2> 199941 T1285 C354 P35128 oass.SolrIndexSearcher.<init> Opening Searcher@e2d9b0 main
[junit4:junit4] 2> 199943 T1285 C354 P35128 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 199943 T1235 C356 P41864 oass.SolrIndexSearcher.<init> Opening Searcher@185ae73 main
[junit4:junit4] 2> 199944 T1235 C356 P41864 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 199944 T1295 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e2d9b0 main{StandardDirectoryReader(segments_6:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 199944 T1243 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@185ae73 main{StandardDirectoryReader(segments_6:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 199945 T1285 C
[...truncated too long message...]
/overseer_elect/election/89925137445945347-127.0.0.1:38411_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89925137445945354-127.0.0.1:56558_-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89925137445945356-127.0.0.1:35128_-n_0000000004 (0)
[junit4:junit4] 1> /solr/clusterstate.json (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[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> "shard":"shard1",
[junit4:junit4] 1> "node_name":"127.0.0.1:38411_",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:38411",
[junit4:junit4] 1> "leader":"true"}}}},
[junit4:junit4] 1> "router":"compositeId"},
[junit4:junit4] 1> "collection1":{
[junit4:junit4] 1> "shards":{"shard1":{
[junit4:junit4] 1> "range":"80000000-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{
[junit4:junit4] 1> "2":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "node_name":"127.0.0.1:41864_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:41864"},
[junit4:junit4] 1> "3":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "node_name":"127.0.0.1:49279_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "state":"down",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:49279"},
[junit4:junit4] 1> "4":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "node_name":"127.0.0.1:56558_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:56558",
[junit4:junit4] 1> "leader":"true"},
[junit4:junit4] 1> "5":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "node_name":"127.0.0.1:35128_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:35128"}}}},
[junit4:junit4] 1> "router":"compositeId"}}
[junit4:junit4] 1> /solr/aliases.json (0)
[junit4:junit4] 1> /solr/collections (2)
[junit4:junit4] 1> /solr/collections/control_collection (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/control_collection/leaders (1)
[junit4:junit4] 1> /solr/collections/control_collection/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "node_name":"127.0.0.1:38411_",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:38411"}
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election/89925137445945347-1-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/control_collection/shards (0)
[junit4:junit4] 1> /solr/collections/collection1 (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/collection1/leaders (1)
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "node_name":"127.0.0.1:56558_",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:56558"}
[junit4:junit4] 1> /solr/collections/collection1/leader_elect (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election (3)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89925137445945358-2-n_0000000004 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89925137445945356-5-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89925137445945354-4-n_0000000002 (0)
[junit4:junit4] 1> /solr/collections/collection1/shards (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=174AA3521A2CF474 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=en_GB -Dtests.timezone=Europe/Malta -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 101s J0 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:41864/collection1lastClient and got 262 from http://127.0.0.1:56558/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([174AA3521A2CF474:96AC2D4A6D739448]: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> 279592 T1199 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 100774 T1198 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 2> 280797 T1291 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 280797 T1291 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> 280797 T1291 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=FastCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=FAST, chunkSize=182), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=FAST, chunkSize=182)), sim=RandomSimilarityProvider(queryNorm=false,coord=no): {}, locale=en_GB, timezone=Europe/Malta
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic i386/Oracle Corporation 1.8.0-ea (32-bit)/cpus=8,threads=3,free=166755832,total=259915776
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestSchemaSimilarityResource, TestPhraseSuggestions, TermVectorComponentTest, TestPerFieldSimilarity, TestReplicationHandler, FileBasedSpellCheckerTest, TestPropInjectDefaults, TestFieldCollectionResource, SynonymTokenizerTest, ZkControllerTest, DocumentBuilderTest, TestIBSimilarityFactory, TermsComponentTest, ScriptEngineTest, DirectSolrConnectionTest, SliceStateUpdateTest, SystemInfoHandlerTest, TestRandomDVFaceting, TestRealTimeGet, TestXIncludeConfig, TestValueSourceCache, SuggesterFSTTest, TestShardHandlerFactory, CoreAdminHandlerTest, LeaderElectionTest, JsonLoaderTest, SimpleFacetsTest, TestFunctionQuery, UnloadDistributedZkTest, TestBadConfig, TestFaceting, SyncSliceTest]
[junit4:junit4] Completed on J0 in 102.05s, 1 test, 1 failure <<< FAILURES!
[...truncated 631 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:386: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:366: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1243: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:887: There were test failures: 297 suites, 1253 tests, 1 failure, 16 ignored (7 assumptions)
Total time: 35 minutes 58 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.8.0-ea-b93 -client -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure