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/24 10:12:36 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/jdk1.7.0_25) - Build # 6213
- Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/6213/
Java: 32bit/jdk1.7.0_25 -server -XX:+UseG1GC
1 tests failed.
FAILED: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:55205/collection1lastClient and got 250 from http://127.0.0.1:34344/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:55205/collection1lastClient and got 250 from http://127.0.0.1:34344/collection1
at __randomizedtesting.SeedInfo.seed([855FC20E98EBFA85:4B94C16EFB49AB9]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
Build Log:
[...truncated 9367 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 63168 T192 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 63173 T192 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1372060463474
[junit4:junit4] 2> 63174 T192 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 63175 T193 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 63275 T192 oasc.ZkTestServer.run start zk server on port:35619
[junit4:junit4] 2> 63276 T192 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 63287 T199 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1bd058e name:ZooKeeperConnection Watcher:127.0.0.1:35619 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 63288 T192 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 63288 T192 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 63292 T192 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 63293 T201 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@18a2f49 name:ZooKeeperConnection Watcher:127.0.0.1:35619/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 63293 T192 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 63294 T192 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 63300 T192 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 63303 T192 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 63306 T192 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 63316 T192 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 63317 T192 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 63336 T192 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 63337 T192 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 63343 T192 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 63343 T192 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 63347 T192 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 63348 T192 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 63351 T192 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 63352 T192 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 63357 T192 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 63358 T192 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 63366 T192 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 63367 T192 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 63386 T192 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 63386 T192 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 63397 T192 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 63397 T192 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 63471 T192 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 63474 T192 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:34181
[junit4:junit4] 2> 63475 T192 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 63475 T192 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 63475 T192 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372060463706
[junit4:junit4] 2> 63476 T192 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372060463706/solr.xml
[junit4:junit4] 2> 63476 T192 oasc.CoreContainer.<init> New CoreContainer 24560448
[junit4:junit4] 2> 63476 T192 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372060463706/'
[junit4:junit4] 2> 63477 T192 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372060463706/'
[junit4:junit4] 2> 63521 T192 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 63521 T192 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 63522 T192 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 63522 T192 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 63522 T192 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 63523 T192 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 63523 T192 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 63523 T192 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 63523 T192 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 63524 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 63528 T192 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 63528 T192 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:35619/solr
[junit4:junit4] 2> 63529 T192 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 63530 T192 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 63532 T212 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@122d921 name:ZooKeeperConnection Watcher:127.0.0.1:35619 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 63533 T192 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 63535 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 63539 T192 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 63540 T214 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1138286 name:ZooKeeperConnection Watcher:127.0.0.1:35619/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 63541 T192 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 63543 T192 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 63547 T192 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 63551 T192 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 63553 T192 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34181_
[junit4:junit4] 2> 63554 T192 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34181_
[junit4:junit4] 2> 63557 T192 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 63569 T192 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 63572 T192 oasc.Overseer.start Overseer (id=89919354534428675-127.0.0.1:34181_-n_0000000000) starting
[junit4:junit4] 2> 63578 T192 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 63583 T216 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 63584 T192 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 63587 T192 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 63590 T192 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 63592 T215 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 63595 T217 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 63595 T217 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 65118 T215 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 65119 T215 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:34181_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34181"}
[junit4:junit4] 2> 65120 T215 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 65120 T215 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 65128 T214 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> 65597 T217 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372060463706/collection1
[junit4:junit4] 2> 65597 T217 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 65598 T217 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 65598 T217 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 65600 T217 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372060463706/collection1/'
[junit4:junit4] 2> 65600 T217 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372060463706/collection1/lib/README' to classloader
[junit4:junit4] 2> 65601 T217 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1372060463706/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 65631 T217 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 65670 T217 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 65672 T217 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 65678 T217 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 66180 T217 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 66180 T217 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 66181 T217 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 66188 T217 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 66190 T217 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 66207 T217 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 66211 T217 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 66215 T217 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 66216 T217 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 66216 T217 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 66216 T217 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 66218 T217 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 66218 T217 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 66218 T217 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 66224 T217 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1372060463706/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372060463474/control/data/
[junit4:junit4] 2> 66225 T217 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@141794b
[junit4:junit4] 2> 66225 T217 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 66226 T217 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/control/data
[junit4:junit4] 2> 66226 T217 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372060463474/control/data/index/
[junit4:junit4] 2> 66226 T217 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372060463474/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 66227 T217 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/control/data/index
[junit4:junit4] 2> 66266 T217 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 66267 T217 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 66269 T217 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 66269 T217 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 66270 T217 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 66270 T217 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 66271 T217 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 66271 T217 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 66271 T217 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 66272 T217 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 66272 T217 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 66274 T217 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 66277 T217 oass.SolrIndexSearcher.<init> Opening Searcher@1536ee0 main
[junit4:junit4] 2> 66278 T217 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 66278 T217 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 66283 T218 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1536ee0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 66285 T217 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 66285 T217 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34181 collection:control_collection shard:shard1
[junit4:junit4] 2> 66286 T217 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 66300 T217 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 66303 T217 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 66304 T217 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 66304 T217 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:34181/collection1/
[junit4:junit4] 2> 66305 T217 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 66305 T217 oasc.SyncStrategy.syncToMe http://127.0.0.1:34181/collection1/ has no replicas
[junit4:junit4] 2> 66305 T217 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:34181/collection1/
[junit4:junit4] 2> 66305 T217 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 66633 T215 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 66669 T214 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> 66730 T217 oasc.ZkController.register We are http://127.0.0.1:34181/collection1/ and leader is http://127.0.0.1:34181/collection1/
[junit4:junit4] 2> 66730 T217 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34181
[junit4:junit4] 2> 66730 T217 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 66730 T217 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 66731 T217 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 66732 T217 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 66734 T192 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 66734 T192 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 66735 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 66738 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 66739 T192 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 66741 T221 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@609cb9 name:ZooKeeperConnection Watcher:127.0.0.1:35619/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 66741 T192 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 66743 T192 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 66746 T192 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 66814 T192 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 66816 T192 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55205
[junit4:junit4] 2> 66817 T192 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 66817 T192 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 66818 T192 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372060467046
[junit4:junit4] 2> 66818 T192 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372060467046/solr.xml
[junit4:junit4] 2> 66818 T192 oasc.CoreContainer.<init> New CoreContainer 10266143
[junit4:junit4] 2> 66819 T192 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372060467046/'
[junit4:junit4] 2> 66819 T192 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372060467046/'
[junit4:junit4] 2> 66882 T192 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 66882 T192 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 66882 T192 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 66883 T192 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 66883 T192 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 66883 T192 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 66884 T192 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 66884 T192 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 66884 T192 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 66885 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 66888 T192 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 66889 T192 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:35619/solr
[junit4:junit4] 2> 66889 T192 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 66890 T192 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 66892 T232 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1f2829e name:ZooKeeperConnection Watcher:127.0.0.1:35619 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 66892 T192 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 66894 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 66898 T192 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 66900 T234 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1e84706 name:ZooKeeperConnection Watcher:127.0.0.1:35619/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 66900 T192 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 66905 T192 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 67909 T192 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55205_
[junit4:junit4] 2> 67910 T192 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55205_
[junit4:junit4] 2> 67913 T221 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 67913 T214 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 67913 T234 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 67913 T214 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> 67921 T235 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 67921 T235 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 68199 T215 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 68200 T215 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:34181__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:34181_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34181"}
[junit4:junit4] 2> 68204 T215 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55205_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55205"}
[junit4:junit4] 2> 68205 T215 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 68205 T215 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 68295 T221 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> 68295 T214 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> 68295 T234 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> 68922 T235 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372060467046/collection1
[junit4:junit4] 2> 68923 T235 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 68924 T235 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 68924 T235 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 68926 T235 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372060467046/collection1/'
[junit4:junit4] 2> 68927 T235 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372060467046/collection1/lib/README' to classloader
[junit4:junit4] 2> 68927 T235 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1372060467046/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 68963 T235 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 68997 T235 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 68999 T235 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 69018 T235 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 69389 T235 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 69389 T235 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 69390 T235 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 69400 T235 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 69404 T235 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 69429 T235 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 69434 T235 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 69465 T235 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 69467 T235 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 69468 T235 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 69468 T235 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 69471 T235 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 69471 T235 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 69471 T235 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 69472 T235 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1372060467046/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/
[junit4:junit4] 2> 69472 T235 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@141794b
[junit4:junit4] 2> 69473 T235 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 69473 T235 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1
[junit4:junit4] 2> 69474 T235 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index/
[junit4:junit4] 2> 69474 T235 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 69475 T235 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index
[junit4:junit4] 2> 69478 T235 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 69478 T235 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 69481 T235 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 69482 T235 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 69483 T235 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 69485 T235 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 69486 T235 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 69486 T235 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 69487 T235 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 69487 T235 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 69488 T235 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 69490 T235 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 69493 T235 oass.SolrIndexSearcher.<init> Opening Searcher@96cf52 main
[junit4:junit4] 2> 69493 T235 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 69493 T235 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 69499 T236 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@96cf52 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 69502 T235 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 69503 T235 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55205 collection:collection1 shard:shard1
[junit4:junit4] 2> 69504 T235 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 69513 T235 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 69516 T235 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 69517 T235 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 69517 T235 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:55205/collection1/
[junit4:junit4] 2> 69517 T235 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 69517 T235 oasc.SyncStrategy.syncToMe http://127.0.0.1:55205/collection1/ has no replicas
[junit4:junit4] 2> 69518 T235 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:55205/collection1/
[junit4:junit4] 2> 69518 T235 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 69803 T215 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 69813 T221 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> 69813 T234 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> 69813 T214 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> 69826 T235 oasc.ZkController.register We are http://127.0.0.1:55205/collection1/ and leader is http://127.0.0.1:55205/collection1/
[junit4:junit4] 2> 69826 T235 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55205
[junit4:junit4] 2> 69827 T235 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 69827 T235 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 69827 T235 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 69829 T235 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 69830 T192 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 69831 T192 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 69832 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 69923 T192 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 69925 T192 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:38280
[junit4:junit4] 2> 69926 T192 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 69926 T192 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 69926 T192 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372060470137
[junit4:junit4] 2> 69927 T192 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372060470137/solr.xml
[junit4:junit4] 2> 69927 T192 oasc.CoreContainer.<init> New CoreContainer 21273044
[junit4:junit4] 2> 69927 T192 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372060470137/'
[junit4:junit4] 2> 69928 T192 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372060470137/'
[junit4:junit4] 2> 69971 T192 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 69972 T192 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 69972 T192 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 69972 T192 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 69973 T192 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 69973 T192 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 69973 T192 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 69974 T192 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 69974 T192 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 69974 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 69978 T192 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 69978 T192 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:35619/solr
[junit4:junit4] 2> 69979 T192 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 69979 T192 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 69981 T248 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6a097e name:ZooKeeperConnection Watcher:127.0.0.1:35619 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 69981 T192 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 69983 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 69987 T192 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 69992 T250 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a3da81 name:ZooKeeperConnection Watcher:127.0.0.1:35619/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 69992 T192 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 69997 T192 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 71001 T192 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38280_
[junit4:junit4] 2> 71003 T192 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38280_
[junit4:junit4] 2> 71006 T221 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> 71006 T214 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 71007 T250 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 71007 T234 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 71007 T214 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> 71007 T234 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> 71010 T221 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 71015 T251 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 71015 T251 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 71322 T215 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 71323 T215 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:55205__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55205_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55205"}
[junit4:junit4] 2> 71327 T215 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:38280_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38280"}
[junit4:junit4] 2> 71327 T215 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 71327 T215 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 71331 T234 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> 71331 T214 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> 71331 T221 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> 71331 T250 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> 72017 T251 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372060470137/collection1
[junit4:junit4] 2> 72017 T251 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 72018 T251 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 72018 T251 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 72020 T251 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372060470137/collection1/'
[junit4:junit4] 2> 72020 T251 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372060470137/collection1/lib/README' to classloader
[junit4:junit4] 2> 72021 T251 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1372060470137/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 72047 T251 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 72091 T251 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 72093 T251 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 72098 T251 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 72520 T251 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 72521 T251 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 72521 T251 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 72528 T251 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 72531 T251 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 72547 T251 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 72552 T251 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 72558 T251 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 72559 T251 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 72560 T251 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 72560 T251 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 72561 T251 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 72562 T251 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 72562 T251 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 72562 T251 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1372060470137/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/
[junit4:junit4] 2> 72563 T251 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@141794b
[junit4:junit4] 2> 72564 T251 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 72564 T251 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2
[junit4:junit4] 2> 72565 T251 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index/
[junit4:junit4] 2> 72565 T251 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 72565 T251 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index
[junit4:junit4] 2> 72569 T251 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 72570 T251 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 72573 T251 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 72574 T251 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 72575 T251 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 72576 T251 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 72577 T251 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 72577 T251 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 72577 T251 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 72578 T251 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 72579 T251 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 72583 T251 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 72588 T251 oass.SolrIndexSearcher.<init> Opening Searcher@1025e3c main
[junit4:junit4] 2> 72589 T251 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 72589 T251 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 72597 T252 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1025e3c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 72600 T251 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 72600 T251 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38280 collection:collection1 shard:shard1
[junit4:junit4] 2> 72605 T251 oasc.ZkController.register We are http://127.0.0.1:38280/collection1/ and leader is http://127.0.0.1:55205/collection1/
[junit4:junit4] 2> 72605 T251 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38280
[junit4:junit4] 2> 72605 T251 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 72606 T251 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C127 name=collection1 org.apache.solr.core.SolrCore@1280526 url=http://127.0.0.1:38280/collection1 node=127.0.0.1:38280_ C127_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:38280_, base_url=http://127.0.0.1:38280}
[junit4:junit4] 2> 72606 T253 C127 P38280 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 72607 T253 C127 P38280 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 72607 T251 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 72607 T253 C127 P38280 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 72608 T253 C127 P38280 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 72608 T192 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 72609 T192 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 72609 T253 C127 P38280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 72609 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 72616 T227 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:38280__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 72682 T192 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 72684 T192 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:34344
[junit4:junit4] 2> 72685 T192 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 72685 T192 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 72685 T192 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372060472913
[junit4:junit4] 2> 72686 T192 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372060472913/solr.xml
[junit4:junit4] 2> 72686 T192 oasc.CoreContainer.<init> New CoreContainer 32444606
[junit4:junit4] 2> 72686 T192 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372060472913/'
[junit4:junit4] 2> 72687 T192 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372060472913/'
[junit4:junit4] 2> 72759 T192 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 72759 T192 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 72759 T192 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 72760 T192 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 72760 T192 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 72760 T192 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 72761 T192 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 72761 T192 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 72761 T192 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 72762 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 72765 T192 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 72766 T192 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:35619/solr
[junit4:junit4] 2> 72766 T192 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 72767 T192 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 72768 T265 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7083c1 name:ZooKeeperConnection Watcher:127.0.0.1:35619 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 72769 T192 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 72771 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 72775 T192 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 72776 T267 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@15a8848 name:ZooKeeperConnection Watcher:127.0.0.1:35619/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 72776 T192 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 72781 T192 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 72839 T215 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 72840 T215 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:38280__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:38280_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38280"}
[junit4:junit4] 2> 72845 T267 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> 72845 T214 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> 72845 T234 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> 72845 T221 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> 72845 T250 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> 73617 T227 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:38280__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 73617 T227 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:38280__collection1&state=recovering&nodeName=127.0.0.1:38280_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 73784 T192 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34344_
[junit4:junit4] 2> 73786 T192 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34344_
[junit4:junit4] 2> 73788 T250 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> 73788 T221 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> 73789 T234 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 73789 T267 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 73789 T234 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> 73789 T214 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 73790 T214 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> 73789 T267 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> 73790 T221 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 73791 T250 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 73795 T268 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 73795 T268 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 74350 T215 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 74351 T215 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:34344_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34344"}
[junit4:junit4] 2> 74351 T215 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 74352 T215 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 74356 T267 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> 74356 T214 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> 74356 T234 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> 74356 T250 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> 74356 T221 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> 74797 T268 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372060472913/collection1
[junit4:junit4] 2> 74797 T268 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 74798 T268 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 74798 T268 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 74800 T268 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372060472913/collection1/'
[junit4:junit4] 2> 74801 T268 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372060472913/collection1/lib/README' to classloader
[junit4:junit4] 2> 74801 T268 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1372060472913/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 74832 T268 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 74887 T268 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 74889 T268 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 74908 T268 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 75267 T268 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 75267 T268 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 75268 T268 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 75274 T268 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 75277 T268 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 75291 T268 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 75294 T268 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 75298 T268 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 75299 T268 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 75299 T268 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 75299 T268 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 75300 T268 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 75301 T268 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 75301 T268 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 75301 T268 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1372060472913/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/
[junit4:junit4] 2> 75301 T268 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@141794b
[junit4:junit4] 2> 75302 T268 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 75302 T268 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3
[junit4:junit4] 2> 75303 T268 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index/
[junit4:junit4] 2> 75303 T268 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 75303 T268 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index
[junit4:junit4] 2> 75306 T268 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 75306 T268 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 75308 T268 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 75308 T268 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 75309 T268 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 75309 T268 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 75310 T268 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 75310 T268 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 75310 T268 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 75311 T268 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 75311 T268 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 75314 T268 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 75316 T268 oass.SolrIndexSearcher.<init> Opening Searcher@15e0164 main
[junit4:junit4] 2> 75317 T268 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 75317 T268 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 75323 T269 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@15e0164 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 75326 T268 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 75326 T268 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34344 collection:collection1 shard:shard1
[junit4:junit4] 2> 75330 T268 oasc.ZkController.register We are http://127.0.0.1:34344/collection1/ and leader is http://127.0.0.1:55205/collection1/
[junit4:junit4] 2> 75330 T268 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34344
[junit4:junit4] 2> 75330 T268 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 75330 T268 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C128 name=collection1 org.apache.solr.core.SolrCore@e6646 url=http://127.0.0.1:34344/collection1 node=127.0.0.1:34344_ C128_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:34344_, base_url=http://127.0.0.1:34344}
[junit4:junit4] 2> 75331 T270 C128 P34344 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 75332 T270 C128 P34344 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 75332 T268 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 75332 T270 C128 P34344 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 75332 T270 C128 P34344 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 75333 T192 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 75334 T192 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 75334 T270 C128 P34344 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 75334 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 75339 T230 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:34344__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 75401 T192 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 75402 T192 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:44954
[junit4:junit4] 2> 75403 T192 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 75403 T192 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 75404 T192 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372060475638
[junit4:junit4] 2> 75404 T192 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372060475638/solr.xml
[junit4:junit4] 2> 75404 T192 oasc.CoreContainer.<init> New CoreContainer 1660885
[junit4:junit4] 2> 75405 T192 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372060475638/'
[junit4:junit4] 2> 75405 T192 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372060475638/'
[junit4:junit4] 2> 75448 T192 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 75449 T192 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 75449 T192 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 75450 T192 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 75450 T192 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 75450 T192 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 75451 T192 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 75451 T192 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 75451 T192 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 75452 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 75455 T192 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 75455 T192 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:35619/solr
[junit4:junit4] 2> 75456 T192 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 75456 T192 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 75458 T282 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@746c52 name:ZooKeeperConnection Watcher:127.0.0.1:35619 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 75458 T192 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 75460 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 75463 T192 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 75464 T284 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13d0353 name:ZooKeeperConnection Watcher:127.0.0.1:35619/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 75464 T192 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 75468 T192 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C129 name=collection1 org.apache.solr.core.SolrCore@1280526 url=http://127.0.0.1:38280/collection1 node=127.0.0.1:38280_ C129_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:38280_, base_url=http://127.0.0.1:38280}
[junit4:junit4] 2> 75618 T253 C129 P38280 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:55205/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 75619 T253 C129 P38280 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38280 START replicas=[http://127.0.0.1:55205/collection1/] nUpdates=100
[junit4:junit4] 2> 75619 T253 C129 P38280 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 75619 T253 C129 P38280 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 75620 T253 C129 P38280 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 75620 T253 C129 P38280 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 75620 T253 C129 P38280 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 75620 T253 C129 P38280 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:55205/collection1/. core=collection1
[junit4:junit4] 2> 75620 T253 C129 P38280 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C130 name=collection1 org.apache.solr.core.SolrCore@1b04710 url=http://127.0.0.1:55205/collection1 node=127.0.0.1:55205_ C130_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55205_, base_url=http://127.0.0.1:55205, leader=true}
[junit4:junit4] 2> 75626 T229 C130 P55205 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 75628 T227 C130 P55205 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 75630 T227 C130 P55205 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 75631 T227 C130 P55205 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 75635 T227 C130 P55205 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 75635 T227 C130 P55205 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 75636 T227 C130 P55205 oass.SolrIndexSearcher.<init> Opening Searcher@de896 realtime
[junit4:junit4] 2> 75636 T227 C130 P55205 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 75636 T227 C130 P55205 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 75637 T253 C129 P38280 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 75638 T253 C129 P38280 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 75640 T227 C130 P55205 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 75640 T227 C130 P55205 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 75641 T253 C129 P38280 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 75641 T253 C129 P38280 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 75641 T253 C129 P38280 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 75644 T229 C130 P55205 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 75644 T253 C129 P38280 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 75645 T253 C129 P38280 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index.20130624105435945
[junit4:junit4] 2> 75645 T253 C129 P38280 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index.20130624105435945 lockFactory=org.apache.lucene.store.NativeFSLockFactory@ca0d89 fullCopy=false
[junit4:junit4] 2> 75648 T228 C130 P55205 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C131 name=collection1 org.apache.solr.core.SolrCore@1280526 url=http://127.0.0.1:38280/collection1 node=127.0.0.1:38280_ C131_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:38280_, base_url=http://127.0.0.1:38280}
[junit4:junit4] 2> 75663 T253 C131 P38280 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 75676 T253 C131 P38280 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 75676 T253 C131 P38280 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 75678 T253 C131 P38280 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 75678 T253 C131 P38280 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 75679 T253 C131 P38280 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 75679 T253 C131 P38280 oass.SolrIndexSearcher.<init> Opening Searcher@1776447 main
[junit4:junit4] 2> 75680 T252 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1776447 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 75681 T253 C131 P38280 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index.20130624105435945 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index.20130624105435945;done=true>>]
[junit4:junit4] 2> 75681 T253 C131 P38280 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index.20130624105435945
[junit4:junit4] 2> 75681 T253 C131 P38280 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index.20130624105435945
[junit4:junit4] 2> 75684 T253 C131 P38280 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 75684 T253 C131 P38280 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 75684 T253 C131 P38280 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 75684 T253 C131 P38280 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 75686 T253 C131 P38280 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 75862 T215 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 75863 T215 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:34344__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:34344_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34344"}
[junit4:junit4] 2> 75869 T215 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:38280__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:38280_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38280"}
[junit4:junit4] 2> 75895 T250 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> 75895 T234 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> 75896 T221 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> 75896 T284 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> 75896 T267 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> 75896 T214 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> 76340 T230 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:34344__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 76340 T230 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:34344__collection1&state=recovering&nodeName=127.0.0.1:34344_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 76471 T192 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:44954_
[junit4:junit4] 2> 76473 T192 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:44954_
[junit4:junit4] 2> 76475 T250 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> 76475 T221 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> 76476 T267 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 76476 T214 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 76476 T234 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 76477 T234 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> 76476 T267 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> 76477 T284 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 76477 T284 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> 76476 T214 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> 76480 T250 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 76481 T221 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 76486 T287 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 76486 T287 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 77405 T215 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 77406 T215 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:44954_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44954"}
[junit4:junit4] 2> 77406 T215 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 77406 T215 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 77411 T250 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> 77411 T214 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> 77412 T234 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> 77412 T221 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> 77412 T267 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> 77412 T284 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> 77488 T287 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372060475638/collection1
[junit4:junit4] 2> 77488 T287 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 77489 T287 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 77489 T287 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 77491 T287 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372060475638/collection1/'
[junit4:junit4] 2> 77491 T287 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372060475638/collection1/lib/README' to classloader
[junit4:junit4] 2> 77491 T287 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1372060475638/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 77520 T287 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 77551 T287 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 77552 T287 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 77557 T287 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 77948 T287 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 77948 T287 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 77949 T287 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 77955 T287 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 77957 T287 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 77975 T287 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 77980 T287 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 77984 T287 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 77985 T287 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 77986 T287 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 77986 T287 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 77987 T287 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 77987 T287 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 77988 T287 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 77988 T287 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1372060475638/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/
[junit4:junit4] 2> 77989 T287 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@141794b
[junit4:junit4] 2> 77989 T287 oasc.SolrCore.initDirectoryFactory solr.StandardDirectoryFactory
[junit4:junit4] 2> 77990 T287 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4
[junit4:junit4] 2> 77990 T287 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index/
[junit4:junit4] 2> 77991 T287 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 77991 T287 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index
[junit4:junit4] 2> 77995 T287 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 77995 T287 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 77998 T287 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 77999 T287 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 78000 T287 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 78001 T287 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 78002 T287 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 78002 T287 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 78003 T287 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 78004 T287 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 78005 T287 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 78008 T287 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 78011 T287 oass.SolrIndexSearcher.<init> Opening Searcher@b05dfd main
[junit4:junit4] 2> 78012 T287 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 78012 T287 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 78019 T288 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@b05dfd main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 78023 T287 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 78023 T287 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:44954 collection:collection1 shard:shard1
[junit4:junit4] 2> 78026 T287 oasc.ZkController.register We are http://127.0.0.1:44954/collection1/ and leader is http://127.0.0.1:55205/collection1/
[junit4:junit4] 2> 78026 T287 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:44954
[junit4:junit4] 2> 78026 T287 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 78027 T287 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C132 name=collection1 org.apache.solr.core.SolrCore@10a9854 url=http://127.0.0.1:44954/collection1 node=127.0.0.1:44954_ C132_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:44954_, base_url=http://127.0.0.1:44954}
[junit4:junit4] 2> 78027 T289 C132 P44954 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 78028 T289 C132 P44954 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 78028 T287 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 78028 T289 C132 P44954 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 78029 T289 C132 P44954 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 78029 T192 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 78030 T192 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 78030 T289 C132 P44954 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 78030 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 78034 T192 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 78036 T192 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 78036 T228 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:44954__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 78036 T192 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 78038 T192 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C133 name=collection1 org.apache.solr.core.SolrCore@e6646 url=http://127.0.0.1:34344/collection1 node=127.0.0.1:34344_ C133_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:34344_, base_url=http://127.0.0.1:34344}
[junit4:junit4] 2> 78341 T270 C133 P34344 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:55205/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 78342 T270 C133 P34344 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34344 START replicas=[http://127.0.0.1:55205/collection1/] nUpdates=100
[junit4:junit4] 2> 78342 T270 C133 P34344 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 78342 T270 C133 P34344 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 78343 T270 C133 P34344 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 78343 T270 C133 P34344 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 78343 T270 C133 P34344 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 78343 T270 C133 P34344 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:55205/collection1/. core=collection1
[junit4:junit4] 2> 78343 T270 C133 P34344 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C134 name=collection1 org.apache.solr.core.SolrCore@1b04710 url=http://127.0.0.1:55205/collection1 node=127.0.0.1:55205_ C134_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55205_, base_url=http://127.0.0.1:55205, leader=true}
[junit4:junit4] 2> 78345 T227 C134 P55205 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 78349 T230 C134 P55205 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 78355 T230 C134 P55205 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> 78355 T230 C134 P55205 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 78356 T230 C134 P55205 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 78356 T230 C134 P55205 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 78357 T270 C133 P34344 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 78357 T270 C133 P34344 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 78359 T227 C134 P55205 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 78360 T270 C133 P34344 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 78360 T270 C133 P34344 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 78360 T270 C133 P34344 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 78363 T230 C134 P55205 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1
[junit4:junit4] 2> 78363 T270 C133 P34344 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 78364 T270 C133 P34344 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index.20130624105438664
[junit4:junit4] 2> 78364 T270 C133 P34344 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index.20130624105438664 lockFactory=org.apache.lucene.store.NativeFSLockFactory@292ae5 fullCopy=false
[junit4:junit4] 2> 78367 T229 C134 P55205 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 2> 78369 T270 C133 P34344 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 78370 T270 C133 P34344 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 78371 T270 C133 P34344 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 78372 T270 C133 P34344 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> 78372 T270 C133 P34344 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 78373 T270 C133 P34344 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 78373 T270 C133 P34344 oass.SolrIndexSearcher.<init> Opening Searcher@188d7f1 main
[junit4:junit4] 2> 78375 T269 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@188d7f1 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 78375 T270 C133 P34344 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index.20130624105438664 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index.20130624105438664;done=true>>]
[junit4:junit4] 2> 78376 T270 C133 P34344 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index.20130624105438664
[junit4:junit4] 2> 78376 T270 C133 P34344 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index.20130624105438664
[junit4:junit4] 2> 78376 T270 C133 P34344 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 78376 T270 C133 P34344 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 78377 T270 C133 P34344 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 78377 T270 C133 P34344 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 78378 T270 C133 P34344 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 78920 T215 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 78921 T215 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:44954__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:44954_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44954"}
[junit4:junit4] 2> 78924 T215 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:34344__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:34344_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34344"}
[junit4:junit4] 2> 78945 T250 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> 78945 T284 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> 78945 T221 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> 78945 T234 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> 78945 T267 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> 78945 T214 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> 79037 T228 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:44954__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 79037 T228 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:44954__collection1&state=recovering&nodeName=127.0.0.1:44954_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 79039 T192 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 80041 T192 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C132_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:44954_, base_url=http://127.0.0.1:44954}
[junit4:junit4] 2> 81038 T289 C132 P44954 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:55205/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 81039 T289 C132 P44954 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:44954 START replicas=[http://127.0.0.1:55205/collection1/] nUpdates=100
[junit4:junit4] 2> 81039 T289 C132 P44954 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 81039 T289 C132 P44954 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 81039 T289 C132 P44954 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 81040 T289 C132 P44954 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 81040 T289 C132 P44954 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 81040 T289 C132 P44954 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:55205/collection1/. core=collection1
[junit4:junit4] 2> 81040 T289 C132 P44954 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 81042 T229 C134 P55205 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 81043 T192 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 81047 T230 C134 P55205 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 81055 T230 C134 P55205 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> 81055 T230 C134 P55205 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 81056 T230 C134 P55205 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 81056 T230 C134 P55205 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 81057 T289 C132 P44954 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 81057 T289 C132 P44954 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 81060 T229 C134 P55205 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 81060 T289 C132 P44954 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 81061 T289 C132 P44954 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 81061 T289 C132 P44954 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 81063 T227 C134 P55205 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=0
[junit4:junit4] 2> 81064 T289 C132 P44954 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 81065 T289 C132 P44954 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index.20130624105441365
[junit4:junit4] 2> 81065 T289 C132 P44954 oash.SnapPuller.fetchLatestIndex Starting download to org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index.20130624105441365 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1e9b2ea fullCopy=false
[junit4:junit4] 2> 81069 T230 C134 P55205 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C135 name=collection1 org.apache.solr.core.SolrCore@10a9854 url=http://127.0.0.1:44954/collection1 node=127.0.0.1:44954_ C135_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:44954_, base_url=http://127.0.0.1:44954}
[junit4:junit4] 2> 81087 T289 C135 P44954 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 81089 T289 C135 P44954 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 81089 T289 C135 P44954 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 81091 T289 C135 P44954 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> 81091 T289 C135 P44954 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 81092 T289 C135 P44954 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 81092 T289 C135 P44954 oass.SolrIndexSearcher.<init> Opening Searcher@1df1f78 main
[junit4:junit4] 2> 81093 T288 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1df1f78 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 81094 T289 C135 P44954 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index.20130624105441365 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index.20130624105441365;done=true>>]
[junit4:junit4] 2> 81094 T289 C135 P44954 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index.20130624105441365
[junit4:junit4] 2> 81095 T289 C135 P44954 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index.20130624105441365
[junit4:junit4] 2> 81095 T289 C135 P44954 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 81095 T289 C135 P44954 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 81095 T289 C135 P44954 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 81096 T289 C135 P44954 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 81097 T289 C135 P44954 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 81956 T215 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 81957 T215 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:44954__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:44954_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:44954"}
[junit4:junit4] 2> 81961 T250 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> 81962 T214 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> 81962 T221 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> 81961 T267 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> 81962 T284 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> 81962 T234 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> 82045 T192 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 82046 T192 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C136 name=collection1 org.apache.solr.core.SolrCore@b5f627 url=http://127.0.0.1:34181/collection1 node=127.0.0.1:34181_ C136_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:34181_, base_url=http://127.0.0.1:34181, leader=true}
[junit4:junit4] 2> 82052 T209 C136 P34181 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 82054 T209 C136 P34181 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> 82055 T209 C136 P34181 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 82085 T209 C136 P34181 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/control/data/index,segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/control/data/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> 82085 T209 C136 P34181 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 82086 T209 C136 P34181 oass.SolrIndexSearcher.<init> Opening Searcher@816c49 main
[junit4:junit4] 2> 82087 T209 C136 P34181 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 82087 T218 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@816c49 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 82088 T209 C136 P34181 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 36
[junit4:junit4] 2> C135_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:44954_, base_url=http://127.0.0.1:44954}
[junit4:junit4] 2> 82099 T280 C135 P44954 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:55205/collection1/, StdNode: http://127.0.0.1:38280/collection1/, StdNode: http://127.0.0.1:34344/collection1/, StdNode: http://127.0.0.1:44954/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 82106 T277 C135 P44954 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C137 name=collection1 org.apache.solr.core.SolrCore@1b04710 url=http://127.0.0.1:55205/collection1 node=127.0.0.1:55205_ C137_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55205_, base_url=http://127.0.0.1:55205, leader=true}
[junit4:junit4] 2> 82107 T229 C137 P55205 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C138 name=collection1 org.apache.solr.core.SolrCore@e6646 url=http://127.0.0.1:34344/collection1 node=127.0.0.1:34344_ C138_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:34344_, base_url=http://127.0.0.1:34344}
[junit4:junit4] 2> 82110 T263 C138 P34344 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C139 name=collection1 org.apache.solr.core.SolrCore@1280526 url=http://127.0.0.1:38280/collection1 node=127.0.0.1:38280_ C139_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:38280_, base_url=http://127.0.0.1:38280}
[junit4:junit4] 2> 82110 T244 C139 P38280 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 82117 T277 C135 P44954 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> 82117 T277 C135 P44954 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 82118 T277 C135 P44954 oass.SolrIndexSearcher.<init> Opening Searcher@19d7e32 main
[junit4:junit4] 2> 82118 T277 C135 P44954 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 82119 T288 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@19d7e32 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 82120 T277 C135 P44954 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 14
[junit4:junit4] 2> 82165 T263 C138 P34344 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> 82165 T244 C139 P38280 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> 82166 T244 C139 P38280 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 82165 T229 C137 P55205 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> 82167 T229 C137 P55205 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 82166 T263 C138 P34344 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 82167 T229 C137 P55205 oass.SolrIndexSearcher.<init> Opening Searcher@130c3da main
[junit4:junit4] 2> 82167 T244 C139 P38280 oass.SolrIndexSearcher.<init> Opening Searcher@84e131 main
[junit4:junit4] 2> 82168 T229 C137 P55205 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 82169 T236 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@130c3da main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 82170 T252 oasc.JmxMonitoredMap.put WARN Failed to register info bean: fieldValueCache javax.management.InstanceAlreadyExistsException: solr/collection1:type=fieldValueCache,id=org.apache.solr.search.FastLRUCache
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:140)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4] 2> at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:302)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1846)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.access$000(SolrCore.java:135)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1723)
[junit4:junit4] 2> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:334)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:166)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 82168 T263 C138 P34344 oass.SolrIndexSearcher.<init> Opening Searcher@1b9009 main
[junit4:junit4] 2> 82170 T244 C139 P38280 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 82170 T252 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@84e131 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 82170 T229 C137 P55205 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 63
[junit4:junit4] 2> 82171 T244 C139 P38280 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 61
[junit4:junit4] 2> 82171 T263 C138 P34344 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 82172 T269 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b9009 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 82173 T263 C138 P34344 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 63
[junit4:junit4] 2> 82173 T280 C135 P44954 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 74
[junit4:junit4] 2> 82175 T192 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 82181 T227 C137 P55205 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 82183 T246 C139 P38280 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 82186 T260 C138 P34344 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 82189 T278 C135 P44954 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 84217 T208 C136 P34181 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438709694611849216)} 0 8
[junit4:junit4] 2> 84229 T261 C138 P34344 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438709694618140672&update.from=http://127.0.0.1:55205/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438709694618140672)} 0 1
[junit4:junit4] 2> 84231 T246 C139 P38280 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438709694618140672&update.from=http://127.0.0.1:55205/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438709694618140672)} 0 1
[junit4:junit4] 2> 84229 T280 C135 P44954 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438709694618140672&update.from=http://127.0.0.1:55205/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438709694618140672)} 0 1
[junit4:junit4] 2> 84232 T227 C137 P55205 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438709694618140672)} 0 10
[junit4:junit4] 2> 84233 T263 C138 P34344 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:*} 0 14
[junit4:junit4] 2> 84239 T210 C136 P34181 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1438709694632820736)]} 0 3
[junit4:junit4] 2> 84257 T278 C135 P44954 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:55205/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438709694646452224)]} 0 3
[junit4:junit4] 2> 84258 T243 C139 P38280 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:55205/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438709694646452224)]} 0 4
[junit4:junit4] 2> 84258 T260 C138 P34344 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:55205/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438709694646452224)]} 0 4
[junit4:junit4] 2> 84259 T230 C137 P55205 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34344/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1438709694646452224)]} 0 10
[junit4:junit4] 2> 84260 T262 C138 P34344 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0]} 0 18
[junit4:junit4] 2> 84265 T209 C136 P34181 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1438709694661132288)]} 0 2
[junit4:junit4] 2> 84274 T244 C139 P38280 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:55205/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438709694666375168)]} 0 2
[junit4:junit4] 2> 84274 T279 C135 P44954 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:55205/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438709694666375168)]} 0 2
[junit4:junit4] 2> 84275 T261 C138 P34344 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:55205/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438709694666375168)]} 0 3
[junit4:junit4] 2> 84276 T229 C137 P55205 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1438709694666375168)]} 0 9
[junit4:junit4] 2> 84281 T207 C136 P34181 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1438709694677909504)]} 0 2
[junit4:junit4] 2> 84286 T227 C137 P55205 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:38280/collection1/]
[junit4:junit4] 2> 84287 T227 C137 P55205 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:38280/collection1/ against:[http://127.0.0.1:38280/collection1/] result:true
[junit4:junit4] 2> 84287 T227 C137 P55205 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:34344/collection1/ against:[http://127.0.0.1:38280/collection1/] result:false
[junit4:junit4] 2> 84287 T227 C137 P55205 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:44954/collection1/ against:[http://127.0.0.1:38280/collection1/] result:false
[junit4:junit4] 2> 84293 T260 C138 P34344 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:55205/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:38280/collection1/&wt=javabin&version=2} {add=[2 (1438709694687346688)]} 0 2
[junit4:junit4] 2> 84294 T277 C135 P44954 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:55205/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:38280/collection1/&wt=javabin&version=2} {add=[2 (1438709694687346688)]} 0 2
[junit4:junit4] 2> 84294 T227 C137 P55205 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34344/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:38280/collection1/&wt=javabin&version=2} {add=[2 (1438709694687346688)]} 0 8
[junit4:junit4] 2> 84295 T263 C138 P34344 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:38280/collection1/&wt=javabin&version=2} {add=[2]} 0 11
[junit4:junit4] 2> 84299 T210 C136 P34181 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1438709694697832448)]} 0 1
[junit4:junit4] 2> 84305 T230 C137 P55205 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:38280/collection1/]
[junit4:junit4] 2> 84305 T230 C137 P55205 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:38280/collection1/ against:[http://127.0.0.1:38280/collection1/] result:true
[junit4:junit4] 2> 84306 T230 C137 P55205 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:34344/collection1/ against:[http://127.0.0.1:38280/collection1/] result:false
[junit4:junit4] 2> 84306 T230 C137 P55205 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:44954/collection1/ against:[http://127.0.0.1:38280/collection1/] result:false
[junit4:junit4] 2> 84312 T280 C135 P44954 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:55205/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:38280/collection1/&wt=javabin&version=2} {add=[3 (1438709694707269632)]} 0 1
[junit4:junit4] 2> 84313 T261 C138 P34344 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:55205/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:38280/collection1/&wt=javabin&version=2} {add=[3 (1438709694707269632)]} 0 2
[junit4:junit4] 2> 84314 T230 C137 P55205 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:34344/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:38280/collection1/&wt=javabin&version=2} {add=[3 (1438709694707269632)]} 0 9
[junit4:junit4] 2> 84314 T262 C138 P34344 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:38280/collection1/&test.distrib.skip.servers=http://127.0.0.1:34344/collection1/&wt=javabin&version=2} {add=[3]} 0 12
[junit4:junit4] 2> 84317 T209 C136 P34181 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 84355 T209 C136 P34181 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/control/data/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/control/data/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> 84355 T209 C136 P34181 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 84371 T209 C136 P34181 oass.SolrIndexSearcher.<init> Opening Searcher@104d8e2 main
[junit4:junit4] 2> 84371 T209 C136 P34181 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 84372 T218 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@104d8e2 main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 84373 T209 C136 P34181 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 56
[junit4:junit4] 2> 84376 T228 C137 P55205 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:55205/collection1/, StdNode: http://127.0.0.1:38280/collection1/, StdNode: http://127.0.0.1:34344/collection1/, StdNode: http://127.0.0.1:44954/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 84378 T229 C137 P55205 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 84379 T260 C138 P34344 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 84379 T278 C135 P44954 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 84381 T245 C139 P38280 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 84425 T245 C139 P38280 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> 84425 T245 C139 P38280 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 84425 T229 C137 P55205 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=5
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_6,generation=6}
[junit4:junit4] 2> 84426 T229 C137 P55205 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 84427 T245 C139 P38280 oass.SolrIndexSearcher.<init> Opening Searcher@b8c4b5 main
[junit4:junit4] 2> 84427 T245 C139 P38280 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 84428 T229 C137 P55205 oass.SolrIndexSearcher.<init> Opening Searcher@134ead0 main
[junit4:junit4] 2> 84428 T252 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@b8c4b5 main{StandardDirectoryReader(segments_4:3:nrt _0(4.4):c2)}
[junit4:junit4] 2> 84429 T229 C137 P55205 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 84429 T245 C139 P38280 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 48
[junit4:junit4] 2> 84430 T236 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@134ead0 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 84430 T229 C137 P55205 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 52
[junit4:junit4] 2> 84435 T278 C135 P44954 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index,segFN=segments_6,generation=6}
[junit4:junit4] 2> 84435 T278 C135 P44954 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 84435 T260 C138 P34344 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> 84436 T260 C138 P34344 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 84437 T278 C135 P44954 oass.SolrIndexSearcher.<init> Opening Searcher@1a62278 main
[junit4:junit4] 2> 84437 T278 C135 P44954 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 84437 T260 C138 P34344 oass.SolrIndexSearcher.<init> Opening Searcher@1412a15 main
[junit4:junit4] 2> 84438 T260 C138 P34344 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 84438 T288 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1a62278 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 84439 T278 C135 P44954 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 60
[junit4:junit4] 2> 84439 T269 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1412a15 main{StandardDirectoryReader(segments_5:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 84440 T260 C138 P34344 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 61
[junit4:junit4] 2> 84440 T228 C137 P55205 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 64
[junit4:junit4] 2> 84441 T192 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 84442 T192 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 84443 T192 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 84446 T227 C137 P55205 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> 84448 T246 C139 P38280 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=2 status=0 QTime=0
[junit4:junit4] 2> 84451 T263 C138 P34344 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 84454 T279 C135 P44954 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 84456 T192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 84462 T261 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2
[junit4:junit4] 2> 84463 T261 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 84467 T230 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 84468 T230 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:55205/collection1/
[junit4:junit4] 2> 84468 T230 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:55205 START replicas=[http://127.0.0.1:38280/collection1/, http://127.0.0.1:34344/collection1/, http://127.0.0.1:44954/collection1/] nUpdates=100
[junit4:junit4] 2> 84475 T260 C138 P34344 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 84475 T243 C139 P38280 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=2
[junit4:junit4] 2> 84476 T230 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:55205 Received 5 versions from 127.0.0.1:34344/collection1/
[junit4:junit4] 2> 84477 T230 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:55205 Our versions are newer. ourLowThreshold=1438709694618140672 otherHigh=1438709694687346688
[junit4:junit4] 2> 84477 T280 C135 P44954 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 84477 T230 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:55205 Received 3 versions from 127.0.0.1:38280/collection1/
[junit4:junit4] 2> 84478 T230 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:55205 Our versions are newer. ourLowThreshold=1438709694618140672 otherHigh=1438709694666375168
[junit4:junit4] 2> 84478 T230 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:55205 Received 5 versions from 127.0.0.1:44954/collection1/
[junit4:junit4] 2> 84478 T230 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:55205 Our versions are newer. ourLowThreshold=1438709694618140672 otherHigh=1438709694687346688
[junit4:junit4] 2> 84478 T230 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:55205 DONE. sync succeeded
[junit4:junit4] 2> 84479 T230 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 84479 T230 oasc.SyncStrategy.syncToMe http://127.0.0.1:55205/collection1/: try and ask http://127.0.0.1:38280/collection1/ to sync
[junit4:junit4] 2> 84479 T230 oasc.SyncStrategy.syncToMe http://127.0.0.1:55205/collection1/: try and ask http://127.0.0.1:34344/collection1/ to sync
[junit4:junit4] 2> 84480 T230 oasc.SyncStrategy.syncToMe http://127.0.0.1:55205/collection1/: try and ask http://127.0.0.1:44954/collection1/ to sync
[junit4:junit4] 2> 84486 T244 C139 P38280 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38280 START replicas=[http://127.0.0.1:55205/collection1/] nUpdates=100
[junit4:junit4] 2> 84487 T279 C135 P44954 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:44954 START replicas=[http://127.0.0.1:55205/collection1/] nUpdates=100
[junit4:junit4] 2> 84486 T263 C138 P34344 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34344 START replicas=[http://127.0.0.1:55205/collection1/] nUpdates=100
[junit4:junit4] 2> 84489 T228 C137 P55205 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 84490 T229 C137 P55205 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 84489 T227 C137 P55205 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 84490 T263 C138 P34344 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:34344 Received 5 versions from 127.0.0.1:55205/collection1/
[junit4:junit4] 2> 84491 T279 C135 P44954 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:44954 Received 5 versions from 127.0.0.1:55205/collection1/
[junit4:junit4] 2> 84491 T263 C138 P34344 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:34344 Our versions are newer. ourLowThreshold=1438709694618140672 otherHigh=1438709694687346688
[junit4:junit4] 2> 84491 T244 C139 P38280 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:38280 Received 5 versions from 127.0.0.1:55205/collection1/
[junit4:junit4] 2> 84492 T263 C138 P34344 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34344 DONE. sync succeeded
[junit4:junit4] 2> 84491 T279 C135 P44954 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:44954 Our versions are newer. ourLowThreshold=1438709694618140672 otherHigh=1438709694687346688
[junit4:junit4] 2> 84492 T263 C138 P34344 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:55205/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=6
[junit4:junit4] 2> 84492 T244 C139 P38280 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:38280 Requesting updates from 127.0.0.1:55205/collection1/n=2 versions=[1438709694707269632, 1438709694687346688]
[junit4:junit4] 2> 84493 T230 oasc.SyncStrategy.syncToMe http://127.0.0.1:55205/collection1/: sync completed with http://127.0.0.1:34344/collection1/
[junit4:junit4] 2> 84493 T279 C135 P44954 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:44954 DONE. sync succeeded
[junit4:junit4] 2> 84494 T279 C135 P44954 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:55205/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=7
[junit4:junit4] 2> 84495 T230 oasc.SyncStrategy.syncToMe http://127.0.0.1:55205/collection1/: sync completed with http://127.0.0.1:44954/collection1/
[junit4:junit4] 2> 84496 T228 C137 P55205 oasc.SolrCore.execute [collection1] webapp= path=/get params={distrib=false&getUpdates=1438709694707269632,1438709694687346688&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 84507 T244 C139 P38280 oasup.LogUpdateProcessor.finish [collection1] {add=[2 (1438709694687346688), 3 (1438709694707269632)]} 0 10
[junit4:junit4] 2> 84508 T244 C139 P38280 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38280 DONE. sync succeeded
[junit4:junit4] 2> 84508 T244 C139 P38280 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:55205/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=22
[junit4:junit4] 2> 84509 T230 oasc.SyncStrategy.syncToMe http://127.0.0.1:55205/collection1/: sync completed with http://127.0.0.1:38280/collection1/
[junit4:junit4] 2> 84509 T230 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={shard=shard1&action=REQUESTSYNCSHARD&core=collection1&collection=collection1&wt=javabin&version=2} status=0 QTime=42
[junit4:junit4] 2> 84510 T261 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/collections params={shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2} status=0 QTime=49
[junit4:junit4] 2> 84511 T192 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 84511 T192 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 84512 T192 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 84513 T192 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 84515 T207 C136 P34181 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 84555 T207 C136 P34181 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/control/data/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/control/data/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> 84555 T207 C136 P34181 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 84556 T207 C136 P34181 oass.SolrIndexSearcher.<init> Opening Searcher@1675e68 main
[junit4:junit4] 2> 84557 T207 C136 P34181 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 84558 T218 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1675e68 main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 84558 T207 C136 P34181 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 43
[junit4:junit4] 2> 84561 T229 C137 P55205 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:55205/collection1/, StdNode: http://127.0.0.1:38280/collection1/, StdNode: http://127.0.0.1:34344/collection1/, StdNode: http://127.0.0.1:44954/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 84564 T227 C137 P55205 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 84564 T262 C138 P34344 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 84564 T277 C135 P44954 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 84564 T245 C139 P38280 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 84585 T227 C137 P55205 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=5
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_6,generation=6}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty1/index,segFN=segments_7,generation=7}
[junit4:junit4] 2> 84586 T227 C137 P55205 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 7
[junit4:junit4] 2> 84586 T227 C137 P55205 oass.SolrIndexSearcher.<init> Opening Searcher@97db9a main
[junit4:junit4] 2> 84587 T227 C137 P55205 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 84588 T236 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@97db9a main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 84588 T227 C137 P55205 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4] 2> 84605 T262 C138 P34344 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty3/index,segFN=segments_6,generation=6}
[junit4:junit4] 2> 84605 T277 C135 P44954 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index,segFN=segments_6,generation=6}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty4/index,segFN=segments_7,generation=7}
[junit4:junit4] 2> 84606 T277 C135 P44954 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 7
[junit4:junit4] 2> 84605 T262 C138 P34344 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 84607 T277 C135 P44954 oass.SolrIndexSearcher.<init> Opening Searcher@a0fa74 main
[junit4:junit4] 2> 84607 T262 C138 P34344 oass.SolrIndexSearcher.<init> Opening Searcher@2146b2 main
[junit4:junit4] 2> 84607 T277 C135 P44954 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 84608 T262 C138 P34344 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 84609 T288 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@a0fa74 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 84609 T269 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2146b2 main{StandardDirectoryReader(segments_5:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 84609 T277 C135 P44954 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 45
[junit4:junit4] 2> 84610 T262 C138 P34344 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 46
[junit4:junit4] 2> 84645 T245 C139 P38280 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index,segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1372060463474/jetty2/index,segFN=segments_5,generation=5}
[junit4:junit4] 2> 84646 T245 C139 P38280 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 84647 T245 C139 P38280 oass.SolrIndexSearcher.<init> Opening Searcher@1360449 main
[junit4:junit4] 2> 84648 T245 C139 P38280 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 84649 T252 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1360449 main{StandardDirectoryReader(segments_5:5:nrt _0(4.4):c2 _1(4.4):c2)}
[junit4:junit4] 2> 84649 T245 C139 P38280 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 85
[junit4:junit4] 2> 84650 T229 C137 P55205 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 89
[junit4:junit4] 2> 84652 T192 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 84655 T228 C137 P55205 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C140 name=collection1 org.apache.solr.core.SolrCore@1280526 url=http://127.0.0.1:38280/collection1 node=127.0.0.1:38280_ C140_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:38280_, base_url=http://127.0.0.1:38280}
[junit4:junit4] 2> 84677 T243 C140 P38280 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=19
[junit4:junit4] 2> ASYNC NEW_CORE C141 name=collection1 org.apache.solr.core.SolrCore@e6646 url=http://127.0.0.1:34344/collection1 node=127.0.0.1:34344_ C141_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:34344_, base_url=http://127.0.0.1:34344}
[junit4:junit4] 2> 84681 T263 C141 P34344 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C142 name=collection1 org.apache.solr.core.SolrCore@10a9854 url=http://127.0.0.1:44954/collection1 node=127.0.0.1:44954_ C142_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:44954_, base_url=http://127.0.0.1:44954}
[junit4:junit4] 2> 84684 T278 C142 P44954 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 86686 T192 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> check const of shard1
[junit4:junit4] 2> client0
[junit4:junit4] 2> PROPS:127.0.0.1:55205__collection1:{"shard":"shard1","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:55205_","base_url":"http://127.0.0.1:55205","leader":"true"}
[junit4:junit4] 2> ASYNC NEW_CORE C143 name=collection1 org.apache.solr.core.SolrCore@1b04710 url=http://127.0.0.1:55205/collection1 node=127.0.0.1:55205_ C143_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55205_, base_url=http://127.0.0.1:55205, leader=true}
[junit4:junit4] 2> 86690 T230 C143 P55205 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:4
[junit4:junit4] 2>
[junit4:junit4] 2> client1
[junit4:junit4] 2> PROPS:127.0.0.1:38280__collection1:{"shard":"shard1","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:38280_","base_url":"http://127.0.0.1:38280"}
[junit4:junit4] 2> 86693 T244 C140 P38280 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:4
[junit4:junit4] 2>
[junit4:junit4] 2> client2
[junit4:junit4] 2> PROPS:127.0.0.1:34344__collection1:{"shard":"shard1","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:34344_","base_url":"http://127.0.0.1:34344"}
[junit4:junit4] 2> 86696 T263 C141 P34344 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> live:true
[junit4:junit4] 2> num:4
[junit4:junit4] 2>
[junit4:junit4] 2> client3
[junit4:junit4] 2> PROPS:127.0.0.1:44954__collection1:{"shard":"shard1","state":"active","core":"collection1","collection":"collection1","node_name":"127.0.0.1:44954_","base_url":"http://127.0.0.1:44954"}
[junit4:junit4] 2> 86698 T279 C142 P44954 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&w
[...truncated too long message...]
"state":"down",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:38280_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:38280"},
[junit4:junit4] 1> "127.0.0.1:34344__collection1":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:34344_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:34344"},
[junit4:junit4] 1> "127.0.0.1:44954__collection1":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:44954_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:44954",
[junit4:junit4] 1> "leader":"true"}}}},
[junit4:junit4] 1> "router":"compositeId"},
[junit4:junit4] 1> "control_collection":{
[junit4:junit4] 1> "shards":{"shard1":{
[junit4:junit4] 1> "range":"80000000-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{"127.0.0.1:34181__collection1":{
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "node_name":"127.0.0.1:34181_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:34181",
[junit4:junit4] 1> "leader":"true"}}}},
[junit4:junit4] 1> "router":"compositeId"}}
[junit4:junit4] 1> /solr/aliases.json (0)
[junit4:junit4] 1> /solr/live_nodes (4)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:34344_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:55205_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:34181_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:44954_ (0)
[junit4:junit4] 1> /solr/overseer (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1> /solr/overseer/queue (0)
[junit4:junit4] 1> /solr/overseer/queue-work (0)
[junit4:junit4] 1> /solr/overseer/collection-queue-work (0)
[junit4:junit4] 1> /solr/collections (2)
[junit4:junit4] 1> /solr/collections/collection1 (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/collection1/shards (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election (3)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89919354534428686-127.0.0.1:55205__collection1-n_0000000004 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89919354534428684-127.0.0.1:44954__collection1-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89919354534428682-127.0.0.1:34344__collection1-n_0000000005 (0)
[junit4:junit4] 1> /solr/collections/collection1/leaders (1)
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:44954_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:44954"}
[junit4:junit4] 1> /solr/collections/control_collection (3)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"configName":"conf1"}
[junit4:junit4] 1> /solr/collections/control_collection/shards (0)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election (1)
[junit4:junit4] 1> /solr/collections/control_collection/leader_elect/shard1/election/89919354534428675-127.0.0.1:34181__collection1-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/control_collection/leaders (1)
[junit4:junit4] 1> /solr/collections/control_collection/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:34181_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:34181"}
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (4)
[junit4:junit4] 1> /solr/overseer_elect/election/89919354534428675-127.0.0.1:34181_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89919354534428686-127.0.0.1:55205_-n_0000000005 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89919354534428682-127.0.0.1:34344_-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89919354534428684-127.0.0.1:44954_-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89919354534428675-127.0.0.1:34181_-n_0000000000"}
[junit4:junit4] 1> /zookeeper (1)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=SyncSliceTest -Dtests.method=testDistribSearch -Dtests.seed=855FC20E98EBFA85 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=hu_HU -Dtests.timezone=Israel -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:55205/collection1lastClient and got 250 from http://127.0.0.1:34344/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([855FC20E98EBFA85:4B94C16EFB49AB9]: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> 164550 T192 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 101385 T191 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 3 leaked thread(s).
[junit4:junit4] 2> 164651 T267 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 164652 T267 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> 164652 T267 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 165738 T284 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 165739 T284 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> 165739 T284 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=hu_HU, timezone=Israel
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic i386/Oracle Corporation 1.7.0_25 (32-bit)/cpus=8,threads=1,free=48557208,total=103809024
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestQueryUtils, SuggesterTest, BadComponentTest, TestTrie, PrimUtilsTest, RegexBoostProcessorTest, TestFaceting, TestSurroundQueryParser, TermsComponentTest, QueryElevationComponentTest, TestCloudManagedSchema, TestPropInjectDefaults, SyncSliceTest]
[junit4:junit4] Completed on J0 in 102.66s, 1 test, 1 failure <<< FAILURES!
[...truncated 778 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:392: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:372: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:1246: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/lucene/common-build.xml:890: There were test failures: 298 suites, 1256 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 40 minutes 40 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_25 -server -XX:+UseG1GC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure