You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/22 08:33:42 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/jdk1.7.0_25) - Build # 6179
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/6179/
Java: 32bit/jdk1.7.0_25 -client -XX:+UseParallelGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:52153/collection1lastClient and got 255 from http://127.0.0.1:34984/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:52153/collection1lastClient and got 255 from http://127.0.0.1:34984/collection1
at __randomizedtesting.SeedInfo.seed([9CCC48FAA3121E43:1D2AC6E2D44D7E7F]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
Build Log:
[...truncated 9759 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 764977 T2079 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 764980 T2079 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./solrtest-SyncSliceTest-1371882369719
[junit4:junit4] 2> 764980 T2079 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 764981 T2080 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 765081 T2079 oasc.ZkTestServer.run start zk server on port:60336
[junit4:junit4] 2> 765082 T2079 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 765295 T2086 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@18dfbe3 name:ZooKeeperConnection Watcher:127.0.0.1:60336 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 765295 T2079 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 765295 T2079 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 765300 T2079 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 765301 T2088 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@127a5bc name:ZooKeeperConnection Watcher:127.0.0.1:60336/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 765301 T2079 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 765301 T2079 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 765304 T2079 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 765306 T2079 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 765307 T2079 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 765309 T2079 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> 765309 T2079 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 765312 T2079 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> 765313 T2079 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 765315 T2079 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> 765316 T2079 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 765318 T2079 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> 765318 T2079 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 765320 T2079 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> 765320 T2079 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 765322 T2079 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> 765323 T2079 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 765324 T2079 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> 765325 T2079 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 765327 T2079 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> 765327 T2079 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 765329 T2079 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> 765329 T2079 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 765388 T2079 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 765392 T2079 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:59807
[junit4:junit4] 2> 765392 T2079 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 765392 T2079 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 765393 T2079 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371882370070
[junit4:junit4] 2> 765393 T2079 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371882370070/solr.xml
[junit4:junit4] 2> 765393 T2079 oasc.CoreContainer.<init> New CoreContainer 9189191
[junit4:junit4] 2> 765394 T2079 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371882370070/'
[junit4:junit4] 2> 765394 T2079 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371882370070/'
[junit4:junit4] 2> 765449 T2079 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 765450 T2079 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 765450 T2079 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 765450 T2079 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 765451 T2079 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 765451 T2079 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 765451 T2079 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 765452 T2079 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 765452 T2079 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 765452 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 765455 T2079 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 765456 T2079 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60336/solr
[junit4:junit4] 2> 765456 T2079 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 765457 T2079 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 765458 T2099 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16c88bb name:ZooKeeperConnection Watcher:127.0.0.1:60336 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 765458 T2079 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 765460 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 765463 T2079 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 765464 T2101 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@131d31 name:ZooKeeperConnection Watcher:127.0.0.1:60336/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 765464 T2079 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 765465 T2079 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 765468 T2079 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 765469 T2079 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 765470 T2079 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:59807_
[junit4:junit4] 2> 765471 T2079 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:59807_
[junit4:junit4] 2> 765473 T2079 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 765476 T2079 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 765477 T2079 oasc.Overseer.start Overseer (id=89907682982100995-127.0.0.1:59807_-n_0000000000) starting
[junit4:junit4] 2> 765479 T2079 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 765481 T2103 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 765481 T2079 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 765483 T2079 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 765485 T2079 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 765487 T2102 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 765489 T2104 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 765490 T2104 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 766989 T2102 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 766990 T2102 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:59807_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59807"}
[junit4:junit4] 2> 766991 T2102 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 766991 T2102 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 766994 T2101 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> 767492 T2104 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371882370070/collection1
[junit4:junit4] 2> 767492 T2104 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 767493 T2104 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 767493 T2104 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 767494 T2104 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371882370070/collection1/'
[junit4:junit4] 2> 767495 T2104 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1371882370070/collection1/lib/README' to classloader
[junit4:junit4] 2> 767495 T2104 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-controljetty-1371882370070/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 767523 T2104 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 767557 T2104 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 767559 T2104 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 767563 T2104 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 768044 T2104 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 768044 T2104 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 768045 T2104 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 768054 T2104 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 768056 T2104 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 768066 T2104 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 768069 T2104 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 768073 T2104 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 768074 T2104 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 768075 T2104 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 768075 T2104 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 768076 T2104 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 768076 T2104 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 768077 T2104 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 768077 T2104 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371882370070/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371882369719/control/data/
[junit4:junit4] 2> 768077 T2104 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1edcb1f
[junit4:junit4] 2> 768078 T2104 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 768078 T2104 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/control/data
[junit4:junit4] 2> 768079 T2104 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371882369719/control/data/index/
[junit4:junit4] 2> 768079 T2104 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371882369719/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 768080 T2104 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/control/data/index
[junit4:junit4] 2> 768083 T2104 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@127e093; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 768084 T2104 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 768086 T2104 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 768086 T2104 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 768087 T2104 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 768088 T2104 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 768089 T2104 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 768089 T2104 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 768089 T2104 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 768090 T2104 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 768090 T2104 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 768094 T2104 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 768099 T2104 oass.SolrIndexSearcher.<init> Opening Searcher@e1e101 main
[junit4:junit4] 2> 768099 T2104 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 768100 T2104 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 768106 T2105 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e1e101 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 768107 T2104 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 768107 T2104 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:59807 collection:control_collection shard:shard1
[junit4:junit4] 2> 768108 T2104 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 768113 T2104 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 768115 T2104 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 768115 T2104 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 768115 T2104 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:59807/collection1/
[junit4:junit4] 2> 768116 T2104 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 768116 T2104 oasc.SyncStrategy.syncToMe http://127.0.0.1:59807/collection1/ has no replicas
[junit4:junit4] 2> 768116 T2104 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:59807/collection1/
[junit4:junit4] 2> 768116 T2104 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 768497 T2102 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 768503 T2101 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> 768524 T2104 oasc.ZkController.register We are http://127.0.0.1:59807/collection1/ and leader is http://127.0.0.1:59807/collection1/
[junit4:junit4] 2> 768524 T2104 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:59807
[junit4:junit4] 2> 768524 T2104 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 768525 T2104 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 768525 T2104 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 768526 T2104 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 768527 T2079 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 768527 T2079 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 768528 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 768532 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 768534 T2079 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 768535 T2108 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5fa178 name:ZooKeeperConnection Watcher:127.0.0.1:60336/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 768535 T2079 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 768536 T2079 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 768538 T2079 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 768618 T2079 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 768620 T2079 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:52153
[junit4:junit4] 2> 768620 T2079 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 768621 T2079 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 768621 T2079 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371882373277
[junit4:junit4] 2> 768621 T2079 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371882373277/solr.xml
[junit4:junit4] 2> 768622 T2079 oasc.CoreContainer.<init> New CoreContainer 4457128
[junit4:junit4] 2> 768622 T2079 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371882373277/'
[junit4:junit4] 2> 768623 T2079 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371882373277/'
[junit4:junit4] 2> 768678 T2079 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 768678 T2079 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 768679 T2079 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 768679 T2079 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 768679 T2079 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 768680 T2079 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 768680 T2079 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 768680 T2079 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 768680 T2079 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 768681 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 768684 T2079 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 768684 T2079 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60336/solr
[junit4:junit4] 2> 768685 T2079 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 768686 T2079 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 768687 T2119 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@18158d1 name:ZooKeeperConnection Watcher:127.0.0.1:60336 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 768687 T2079 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 768688 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 768692 T2079 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 768693 T2121 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d83e27 name:ZooKeeperConnection Watcher:127.0.0.1:60336/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 768693 T2079 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 768696 T2079 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 769699 T2079 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:52153_
[junit4:junit4] 2> 769700 T2079 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:52153_
[junit4:junit4] 2> 769702 T2108 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 769702 T2101 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 769703 T2121 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 769703 T2101 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> 769707 T2122 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 769707 T2122 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 770006 T2102 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 770006 T2102 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:59807__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:59807_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:59807"}
[junit4:junit4] 2> 770008 T2102 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:52153_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52153"}
[junit4:junit4] 2> 770009 T2102 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 770009 T2102 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 770011 T2108 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> 770011 T2121 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> 770011 T2101 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> 770708 T2122 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371882373277/collection1
[junit4:junit4] 2> 770708 T2122 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 770709 T2122 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 770709 T2122 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 770710 T2122 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371882373277/collection1/'
[junit4:junit4] 2> 770711 T2122 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1371882373277/collection1/lib/README' to classloader
[junit4:junit4] 2> 770711 T2122 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty1-1371882373277/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 770751 T2122 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 770798 T2122 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 770799 T2122 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 770803 T2122 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 771191 T2122 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 771192 T2122 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 771192 T2122 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 771198 T2122 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 771201 T2122 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 771211 T2122 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 771214 T2122 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 771216 T2122 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 771217 T2122 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 771217 T2122 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 771218 T2122 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 771218 T2122 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 771219 T2122 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 771219 T2122 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 771219 T2122 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371882373277/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/
[junit4:junit4] 2> 771219 T2122 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1edcb1f
[junit4:junit4] 2> 771220 T2122 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 771220 T2122 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1
[junit4:junit4] 2> 771220 T2122 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index/
[junit4:junit4] 2> 771221 T2122 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 771221 T2122 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index
[junit4:junit4] 2> 771224 T2122 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 771224 T2122 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 771225 T2122 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 771226 T2122 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 771226 T2122 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 771227 T2122 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 771227 T2122 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 771227 T2122 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 771228 T2122 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 771228 T2122 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 771228 T2122 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 771231 T2122 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 771234 T2122 oass.SolrIndexSearcher.<init> Opening Searcher@1b59fe9 main
[junit4:junit4] 2> 771234 T2122 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 771234 T2122 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 771239 T2123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b59fe9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 771241 T2122 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 771241 T2122 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:52153 collection:collection1 shard:shard1
[junit4:junit4] 2> 771242 T2122 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 771247 T2122 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 771248 T2122 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 771248 T2122 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 771248 T2122 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52153/collection1/
[junit4:junit4] 2> 771249 T2122 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 771249 T2122 oasc.SyncStrategy.syncToMe http://127.0.0.1:52153/collection1/ has no replicas
[junit4:junit4] 2> 771249 T2122 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:52153/collection1/
[junit4:junit4] 2> 771249 T2122 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 771516 T2102 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 771528 T2108 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> 771528 T2121 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> 771528 T2101 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> 771553 T2122 oasc.ZkController.register We are http://127.0.0.1:52153/collection1/ and leader is http://127.0.0.1:52153/collection1/
[junit4:junit4] 2> 771554 T2122 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:52153
[junit4:junit4] 2> 771554 T2122 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 771554 T2122 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 771554 T2122 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 771556 T2122 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 771556 T2079 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 771557 T2079 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 771557 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 771631 T2079 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 771633 T2079 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:36971
[junit4:junit4] 2> 771634 T2079 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 771634 T2079 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 771634 T2079 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371882376300
[junit4:junit4] 2> 771635 T2079 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371882376300/solr.xml
[junit4:junit4] 2> 771635 T2079 oasc.CoreContainer.<init> New CoreContainer 13166435
[junit4:junit4] 2> 771635 T2079 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371882376300/'
[junit4:junit4] 2> 771636 T2079 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371882376300/'
[junit4:junit4] 2> 771684 T2079 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 771685 T2079 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 771685 T2079 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 771685 T2079 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 771686 T2079 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 771686 T2079 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 771686 T2079 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 771687 T2079 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 771687 T2079 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 771687 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 771690 T2079 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 771691 T2079 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60336/solr
[junit4:junit4] 2> 771691 T2079 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 771692 T2079 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 771693 T2135 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3bc43 name:ZooKeeperConnection Watcher:127.0.0.1:60336 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 771693 T2079 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 771695 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 771698 T2079 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 771699 T2137 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19da535 name:ZooKeeperConnection Watcher:127.0.0.1:60336/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 771699 T2079 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 771701 T2079 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 772704 T2079 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:36971_
[junit4:junit4] 2> 772705 T2079 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:36971_
[junit4:junit4] 2> 772707 T2101 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 772708 T2121 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 772708 T2101 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> 772707 T2108 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 772708 T2108 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> 772708 T2137 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 772708 T2121 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> 772715 T2138 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 772715 T2138 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 773033 T2102 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 773033 T2102 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:52153__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:52153_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:52153"}
[junit4:junit4] 2> 773036 T2102 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:36971_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:36971"}
[junit4:junit4] 2> 773036 T2102 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 773036 T2102 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 773038 T2101 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> 773038 T2108 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> 773039 T2137 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> 773039 T2121 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> 773716 T2138 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371882376300/collection1
[junit4:junit4] 2> 773716 T2138 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 773717 T2138 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 773717 T2138 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 773719 T2138 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371882376300/collection1/'
[junit4:junit4] 2> 773719 T2138 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1371882376300/collection1/lib/README' to classloader
[junit4:junit4] 2> 773719 T2138 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty2-1371882376300/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 773747 T2138 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 773781 T2138 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 773783 T2138 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 773787 T2138 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 774153 T2138 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 774154 T2138 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 774154 T2138 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 774160 T2138 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 774163 T2138 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 774172 T2138 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 774174 T2138 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 774177 T2138 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 774178 T2138 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 774178 T2138 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 774178 T2138 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 774179 T2138 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 774179 T2138 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 774179 T2138 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 774179 T2138 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371882376300/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/
[junit4:junit4] 2> 774180 T2138 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1edcb1f
[junit4:junit4] 2> 774180 T2138 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 774180 T2138 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2
[junit4:junit4] 2> 774181 T2138 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index/
[junit4:junit4] 2> 774181 T2138 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 774181 T2138 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index
[junit4:junit4] 2> 774184 T2138 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@13bca46; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 774184 T2138 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 774186 T2138 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 774186 T2138 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 774186 T2138 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 774187 T2138 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 774187 T2138 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 774188 T2138 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 774188 T2138 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 774188 T2138 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 774189 T2138 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 774191 T2138 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 774194 T2138 oass.SolrIndexSearcher.<init> Opening Searcher@281086 main
[junit4:junit4] 2> 774194 T2138 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 774194 T2138 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 774200 T2139 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@281086 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 774202 T2138 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 774202 T2138 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:36971 collection:collection1 shard:shard1
[junit4:junit4] 2> 774206 T2138 oasc.ZkController.register We are http://127.0.0.1:36971/collection1/ and leader is http://127.0.0.1:52153/collection1/
[junit4:junit4] 2> 774206 T2138 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:36971
[junit4:junit4] 2> 774206 T2138 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 774206 T2138 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C813 name=collection1 org.apache.solr.core.SolrCore@12963a4 url=http://127.0.0.1:36971/collection1 node=127.0.0.1:36971_ C813_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:36971_, base_url=http://127.0.0.1:36971}
[junit4:junit4] 2> 774207 T2140 C813 P36971 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 774207 T2140 C813 P36971 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 774207 T2138 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 774207 T2140 C813 P36971 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 774208 T2140 C813 P36971 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 774208 T2079 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 774209 T2079 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 774209 T2140 C813 P36971 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 774209 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 774213 T2117 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:36971__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 774300 T2079 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 774302 T2079 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:34984
[junit4:junit4] 2> 774302 T2079 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 774303 T2079 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 774303 T2079 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371882378952
[junit4:junit4] 2> 774303 T2079 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371882378952/solr.xml
[junit4:junit4] 2> 774304 T2079 oasc.CoreContainer.<init> New CoreContainer 12805727
[junit4:junit4] 2> 774304 T2079 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371882378952/'
[junit4:junit4] 2> 774304 T2079 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371882378952/'
[junit4:junit4] 2> 774355 T2079 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 774355 T2079 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 774356 T2079 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 774356 T2079 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 774356 T2079 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 774357 T2079 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 774357 T2079 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 774357 T2079 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 774358 T2079 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 774358 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 774361 T2079 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 774361 T2079 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60336/solr
[junit4:junit4] 2> 774362 T2079 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 774363 T2079 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 774364 T2152 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1355fbb name:ZooKeeperConnection Watcher:127.0.0.1:60336 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 774364 T2079 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 774366 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 774369 T2079 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 774370 T2154 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1183c53 name:ZooKeeperConnection Watcher:127.0.0.1:60336/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 774370 T2079 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 774372 T2079 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 774542 T2102 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 774543 T2102 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:36971__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:36971_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:36971"}
[junit4:junit4] 2> 774545 T2108 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> 774545 T2101 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> 774546 T2154 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> 774545 T2121 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> 774545 T2137 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> 775213 T2117 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:36971__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 775214 T2117 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:36971__collection1&state=recovering&nodeName=127.0.0.1:36971_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 775375 T2079 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:34984_
[junit4:junit4] 2> 775376 T2079 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:34984_
[junit4:junit4] 2> 775378 T2108 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 775378 T2121 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 775378 T2137 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 775378 T2108 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> 775378 T2154 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 775378 T2101 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 775379 T2154 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> 775379 T2137 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> 775378 T2121 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> 775379 T2101 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> 775385 T2155 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 775385 T2155 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 776048 T2102 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 776049 T2102 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:34984_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34984"}
[junit4:junit4] 2> 776049 T2102 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 776049 T2102 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 776053 T2101 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> 776053 T2121 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> 776054 T2154 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> 776053 T2108 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> 776054 T2137 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> 776387 T2155 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371882378952/collection1
[junit4:junit4] 2> 776387 T2155 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 776388 T2155 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 776388 T2155 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 776389 T2155 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371882378952/collection1/'
[junit4:junit4] 2> 776390 T2155 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1371882378952/collection1/lib/README' to classloader
[junit4:junit4] 2> 776390 T2155 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty3-1371882378952/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 776418 T2155 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 776452 T2155 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 776453 T2155 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 776457 T2155 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 776822 T2155 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 776823 T2155 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 776823 T2155 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 776829 T2155 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 776832 T2155 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 776842 T2155 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 776845 T2155 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 776847 T2155 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 776848 T2155 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 776848 T2155 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 776849 T2155 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 776850 T2155 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 776850 T2155 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 776850 T2155 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 776850 T2155 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371882378952/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/
[junit4:junit4] 2> 776850 T2155 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1edcb1f
[junit4:junit4] 2> 776851 T2155 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 776851 T2155 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3
[junit4:junit4] 2> 776851 T2155 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index/
[junit4:junit4] 2> 776852 T2155 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 776852 T2155 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index
[junit4:junit4] 2> 776855 T2155 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@17710f8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 776855 T2155 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 776856 T2155 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 776857 T2155 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 776857 T2155 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 776858 T2155 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 776858 T2155 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 776858 T2155 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 776859 T2155 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 776859 T2155 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 776860 T2155 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 776862 T2155 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 776865 T2155 oass.SolrIndexSearcher.<init> Opening Searcher@14a38cf main
[junit4:junit4] 2> 776865 T2155 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 776865 T2155 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 776870 T2156 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@14a38cf main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 776872 T2155 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 776872 T2155 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:34984 collection:collection1 shard:shard1
[junit4:junit4] 2> 776875 T2155 oasc.ZkController.register We are http://127.0.0.1:34984/collection1/ and leader is http://127.0.0.1:52153/collection1/
[junit4:junit4] 2> 776875 T2155 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:34984
[junit4:junit4] 2> 776875 T2155 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 776875 T2155 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C814 name=collection1 org.apache.solr.core.SolrCore@bb770e url=http://127.0.0.1:34984/collection1 node=127.0.0.1:34984_ C814_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:34984_, base_url=http://127.0.0.1:34984}
[junit4:junit4] 2> 776876 T2157 C814 P34984 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 776876 T2155 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 776876 T2157 C814 P34984 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 776877 T2157 C814 P34984 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 776877 T2157 C814 P34984 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 776877 T2079 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 776877 T2079 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 776877 T2157 C814 P34984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 776878 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 776881 T2115 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:34984__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 776961 T2079 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 776963 T2079 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:56116
[junit4:junit4] 2> 776964 T2079 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 776964 T2079 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 776964 T2079 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371882381619
[junit4:junit4] 2> 776964 T2079 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371882381619/solr.xml
[junit4:junit4] 2> 776965 T2079 oasc.CoreContainer.<init> New CoreContainer 3636218
[junit4:junit4] 2> 776965 T2079 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371882381619/'
[junit4:junit4] 2> 776965 T2079 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371882381619/'
[junit4:junit4] 2> 777016 T2079 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 777016 T2079 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 777017 T2079 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 777017 T2079 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 777017 T2079 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 777018 T2079 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 777018 T2079 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 777018 T2079 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 777019 T2079 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 777019 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 777022 T2079 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 777022 T2079 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:60336/solr
[junit4:junit4] 2> 777023 T2079 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 777023 T2079 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 777025 T2169 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11ba599 name:ZooKeeperConnection Watcher:127.0.0.1:60336 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 777025 T2079 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 777026 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 777029 T2079 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 777030 T2171 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8dff23 name:ZooKeeperConnection Watcher:127.0.0.1:60336/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 777030 T2079 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 777033 T2079 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C815 name=collection1 org.apache.solr.core.SolrCore@12963a4 url=http://127.0.0.1:36971/collection1 node=127.0.0.1:36971_ C815_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:36971_, base_url=http://127.0.0.1:36971}
[junit4:junit4] 2> 777215 T2140 C815 P36971 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52153/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 777215 T2140 C815 P36971 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:36971 START replicas=[http://127.0.0.1:52153/collection1/] nUpdates=100
[junit4:junit4] 2> 777215 T2140 C815 P36971 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 777216 T2140 C815 P36971 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 777216 T2140 C815 P36971 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 777216 T2140 C815 P36971 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 777216 T2140 C815 P36971 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 777216 T2140 C815 P36971 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52153/collection1/. core=collection1
[junit4:junit4] 2> 777217 T2140 C815 P36971 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C816 name=collection1 org.apache.solr.core.SolrCore@64028d url=http://127.0.0.1:52153/collection1 node=127.0.0.1:52153_ C816_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52153_, base_url=http://127.0.0.1:52153, leader=true}
[junit4:junit4] 2> 777221 T2117 C816 P52153 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> 777221 T2116 C816 P52153 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 777223 T2116 C816 P52153 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 777223 T2116 C816 P52153 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 777234 T2116 C816 P52153 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 777234 T2116 C816 P52153 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 777235 T2116 C816 P52153 oass.SolrIndexSearcher.<init> Opening Searcher@623d93 realtime
[junit4:junit4] 2> 777235 T2116 C816 P52153 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 777235 T2116 C816 P52153 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 14
[junit4:junit4] 2> 777236 T2140 C815 P36971 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 777237 T2140 C815 P36971 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 777238 T2117 C816 P52153 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 777239 T2117 C816 P52153 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 777239 T2140 C815 P36971 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 777239 T2140 C815 P36971 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 777239 T2140 C815 P36971 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 777241 T2116 C816 P52153 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 777242 T2140 C815 P36971 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 777242 T2140 C815 P36971 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index.20130622072621981
[junit4:junit4] 2> 777242 T2140 C815 P36971 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index.20130622072621981 lockFactory=org.apache.lucene.store.NativeFSLockFactory@14ad2ac; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 777245 T2114 C816 P52153 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 777246 T2140 C815 P36971 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 777254 T2140 C815 P36971 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 777254 T2140 C815 P36971 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 777256 T2140 C815 P36971 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@13bca46; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@13bca46; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 777256 T2140 C815 P36971 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 777256 T2140 C815 P36971 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 777257 T2140 C815 P36971 oass.SolrIndexSearcher.<init> Opening Searcher@f07732 main
[junit4:junit4] 2> 777258 T2139 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@f07732 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 777258 T2140 C815 P36971 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index.20130622072621981 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index.20130622072621981;done=true>>]
[junit4:junit4] 2> 777259 T2140 C815 P36971 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index.20130622072621981
[junit4:junit4] 2> 777259 T2140 C815 P36971 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index.20130622072621981
[junit4:junit4] 2> 777259 T2140 C815 P36971 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 777259 T2140 C815 P36971 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 777259 T2140 C815 P36971 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 777259 T2140 C815 P36971 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 777261 T2140 C815 P36971 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 777557 T2102 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 777557 T2102 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:34984__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:34984_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34984"}
[junit4:junit4] 2> 777560 T2102 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:36971__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:36971_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:36971"}
[junit4:junit4] 2> 777575 T2101 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> 777575 T2154 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> 777575 T2137 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> 777575 T2121 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> 777575 T2108 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> 777575 T2171 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> 777882 T2115 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:34984__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 777882 T2115 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:34984__collection1&state=recovering&nodeName=127.0.0.1:34984_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 778035 T2079 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56116_
[junit4:junit4] 2> 778037 T2079 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:56116_
[junit4:junit4] 2> 778039 T2171 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> 778040 T2137 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 778040 T2108 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 778040 T2137 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> 778040 T2121 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 778041 T2121 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> 778041 T2154 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 778040 T2101 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 778041 T2154 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> 778040 T2108 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> 778042 T2171 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 778041 T2101 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> 778046 T2174 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 778046 T2174 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 779081 T2102 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 779081 T2102 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:56116_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56116"}
[junit4:junit4] 2> 779082 T2102 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 779082 T2102 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 779085 T2108 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> 779085 T2121 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> 779085 T2171 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> 779086 T2137 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> 779085 T2154 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> 779085 T2101 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> C814_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:34984_, base_url=http://127.0.0.1:34984}
[junit4:junit4] 2> 779883 T2157 C814 P34984 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52153/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 779883 T2157 C814 P34984 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34984 START replicas=[http://127.0.0.1:52153/collection1/] nUpdates=100
[junit4:junit4] 2> 779884 T2157 C814 P34984 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 779884 T2157 C814 P34984 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 779884 T2157 C814 P34984 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 779884 T2157 C814 P34984 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 779885 T2157 C814 P34984 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 779885 T2157 C814 P34984 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52153/collection1/. core=collection1
[junit4:junit4] 2> 779885 T2157 C814 P34984 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 779885 T2116 C816 P52153 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> 779890 T2117 C816 P52153 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 779904 T2117 C816 P52153 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 779904 T2117 C816 P52153 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 779905 T2117 C816 P52153 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 779905 T2117 C816 P52153 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 15
[junit4:junit4] 2> 779906 T2157 C814 P34984 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 779906 T2157 C814 P34984 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 779907 T2116 C816 P52153 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 779908 T2157 C814 P34984 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 779908 T2157 C814 P34984 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 779908 T2157 C814 P34984 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 779910 T2114 C816 P52153 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=0
[junit4:junit4] 2> 779911 T2157 C814 P34984 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 779911 T2157 C814 P34984 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index.20130622072624650
[junit4:junit4] 2> 779912 T2157 C814 P34984 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index.20130622072624650 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16c2dc; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 779914 T2117 C816 P52153 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> 779915 T2157 C814 P34984 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 779917 T2157 C814 P34984 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 779917 T2157 C814 P34984 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 779918 T2157 C814 P34984 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@17710f8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@17710f8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 779919 T2157 C814 P34984 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 779919 T2157 C814 P34984 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 779919 T2157 C814 P34984 oass.SolrIndexSearcher.<init> Opening Searcher@51e16c main
[junit4:junit4] 2> 779920 T2156 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@51e16c main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 779921 T2157 C814 P34984 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index.20130622072624650 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index.20130622072624650;done=true>>]
[junit4:junit4] 2> 779921 T2157 C814 P34984 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index.20130622072624650
[junit4:junit4] 2> 779921 T2157 C814 P34984 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index.20130622072624650
[junit4:junit4] 2> 779921 T2157 C814 P34984 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 779922 T2157 C814 P34984 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 779922 T2157 C814 P34984 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 779922 T2157 C814 P34984 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 779923 T2157 C814 P34984 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 780047 T2174 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371882381619/collection1
[junit4:junit4] 2> 780048 T2174 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 780049 T2174 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 780049 T2174 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 780050 T2174 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371882381619/collection1/'
[junit4:junit4] 2> 780050 T2174 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1371882381619/collection1/lib/README' to classloader
[junit4:junit4] 2> 780050 T2174 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-jetty4-1371882381619/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 780081 T2174 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 780115 T2174 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 780117 T2174 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 780121 T2174 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 780492 T2174 oass.ByteField.init WARN ByteField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 780492 T2174 oass.ShortField.init WARN ShortField is deprecated and will be removed in 5.0. You should use TrieIntField instead.
[junit4:junit4] 2> 780493 T2174 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 780499 T2174 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 780502 T2174 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 780510 T2174 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 780513 T2174 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 780516 T2174 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 780517 T2174 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 780517 T2174 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 780517 T2174 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 780517 T2174 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 780518 T2174 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 780518 T2174 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 780518 T2174 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371882381619/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/
[junit4:junit4] 2> 780518 T2174 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1edcb1f
[junit4:junit4] 2> 780519 T2174 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 780519 T2174 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4
[junit4:junit4] 2> 780519 T2174 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index/
[junit4:junit4] 2> 780520 T2174 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 780520 T2174 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index
[junit4:junit4] 2> 780536 T2174 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@e726b1; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 780536 T2174 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 780537 T2174 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 780538 T2174 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 780538 T2174 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 780539 T2174 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 780539 T2174 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 780539 T2174 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 780541 T2174 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 780541 T2174 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 780542 T2174 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 780544 T2174 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 780547 T2174 oass.SolrIndexSearcher.<init> Opening Searcher@615611 main
[junit4:junit4] 2> 780547 T2174 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 780547 T2174 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 780553 T2177 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@615611 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 780555 T2174 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 780555 T2174 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:56116 collection:collection1 shard:shard1
[junit4:junit4] 2> 780557 T2174 oasc.ZkController.register We are http://127.0.0.1:56116/collection1/ and leader is http://127.0.0.1:52153/collection1/
[junit4:junit4] 2> 780558 T2174 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56116
[junit4:junit4] 2> 780558 T2174 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 780558 T2174 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C817 name=collection1 org.apache.solr.core.SolrCore@a55bc2 url=http://127.0.0.1:56116/collection1 node=127.0.0.1:56116_ C817_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:56116_, base_url=http://127.0.0.1:56116}
[junit4:junit4] 2> 780558 T2178 C817 P56116 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 780559 T2178 C817 P56116 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 780559 T2174 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 780559 T2178 C817 P56116 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 780560 T2178 C817 P56116 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 780560 T2079 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1
[junit4:junit4] 2> 780560 T2178 C817 P56116 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 780560 T2079 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 780561 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 780564 T2079 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 780564 T2114 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:56116__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 780565 T2079 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 780565 T2079 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 780565 T2079 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 780590 T2102 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 780591 T2102 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:34984__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:34984_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:34984"}
[junit4:junit4] 2> 780593 T2102 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:56116__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:56116_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56116"}
[junit4:junit4] 2> 780596 T2108 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> 780596 T2154 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> 780596 T2171 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> 780596 T2101 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> 780596 T2121 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> 780596 T2137 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> 781565 T2114 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:56116__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 781565 T2114 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:56116__collection1&state=recovering&nodeName=127.0.0.1:56116_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 781566 T2079 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 782568 T2079 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C817_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:56116_, base_url=http://127.0.0.1:56116}
[junit4:junit4] 2> 783566 T2178 C817 P56116 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:52153/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 783566 T2178 C817 P56116 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56116 START replicas=[http://127.0.0.1:52153/collection1/] nUpdates=100
[junit4:junit4] 2> 783567 T2178 C817 P56116 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 783567 T2178 C817 P56116 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 783567 T2178 C817 P56116 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 783567 T2178 C817 P56116 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 783567 T2178 C817 P56116 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 783567 T2178 C817 P56116 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:52153/collection1/. core=collection1
[junit4:junit4] 2> 783568 T2178 C817 P56116 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C818 name=collection1 org.apache.solr.core.SolrCore@64028d url=http://127.0.0.1:52153/collection1 node=127.0.0.1:52153_ C818_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:52153_, base_url=http://127.0.0.1:52153, leader=true}
[junit4:junit4] 2> 783568 T2114 C818 P52153 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> 783569 T2079 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 783571 T2115 C818 P52153 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 783584 T2115 C818 P52153 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 783584 T2115 C818 P52153 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 783585 T2115 C818 P52153 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 783585 T2115 C818 P52153 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 14
[junit4:junit4] 2> 783586 T2178 C817 P56116 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 783586 T2178 C817 P56116 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 783587 T2117 C818 P52153 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 783588 T2178 C817 P56116 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 783588 T2178 C817 P56116 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 783588 T2178 C817 P56116 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 783590 T2114 C818 P52153 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> 783590 T2178 C817 P56116 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 783591 T2178 C817 P56116 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index.20130622072628330
[junit4:junit4] 2> 783592 T2178 C817 P56116 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index.20130622072628330 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c0332c; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 783594 T2115 C818 P52153 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> 783595 T2178 C817 P56116 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 783597 T2178 C817 P56116 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 783597 T2178 C817 P56116 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 783598 T2178 C817 P56116 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@e726b1; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@e726b1; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 783599 T2178 C817 P56116 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 783599 T2178 C817 P56116 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 783599 T2178 C817 P56116 oass.SolrIndexSearcher.<init> Opening Searcher@84e0a0 main
[junit4:junit4] 2> 783600 T2177 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@84e0a0 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 783601 T2178 C817 P56116 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index.20130622072628330 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index.20130622072628330;done=true>>]
[junit4:junit4] 2> 783601 T2178 C817 P56116 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index.20130622072628330
[junit4:junit4] 2> 783601 T2178 C817 P56116 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index.20130622072628330
[junit4:junit4] 2> 783602 T2178 C817 P56116 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 783602 T2178 C817 P56116 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 783602 T2178 C817 P56116 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 783602 T2178 C817 P56116 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 783603 T2178 C817 P56116 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 783604 T2102 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 783604 T2102 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:56116__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:56116_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56116"}
[junit4:junit4] 2> 783607 T2108 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> 783607 T2121 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> 783607 T2101 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> 783607 T2137 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> 783607 T2171 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> 783608 T2154 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> 784571 T2079 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 784572 T2079 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C819 name=collection1 org.apache.solr.core.SolrCore@1c30d07 url=http://127.0.0.1:59807/collection1 node=127.0.0.1:59807_ C819_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:59807_, base_url=http://127.0.0.1:59807, leader=true}
[junit4:junit4] 2> 784577 T2097 C819 P59807 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 784579 T2097 C819 P59807 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@127e093; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 784579 T2097 C819 P59807 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 784584 T2097 C819 P59807 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@127e093; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@127e093; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 784584 T2097 C819 P59807 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 784585 T2097 C819 P59807 oass.SolrIndexSearcher.<init> Opening Searcher@5a2785 main
[junit4:junit4] 2> 784585 T2097 C819 P59807 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 784586 T2105 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5a2785 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 784586 T2097 C819 P59807 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> C817_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:56116_, base_url=http://127.0.0.1:56116}
[junit4:junit4] 2> 784593 T2165 C817 P56116 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:52153/collection1/, StdNode: http://127.0.0.1:36971/collection1/, StdNode: http://127.0.0.1:34984/collection1/, StdNode: http://127.0.0.1:56116/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 784596 T2166 C817 P56116 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 784596 T2115 C818 P52153 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C820 name=collection1 org.apache.solr.core.SolrCore@bb770e url=http://127.0.0.1:34984/collection1 node=127.0.0.1:34984_ C820_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:34984_, base_url=http://127.0.0.1:34984}
[junit4:junit4] 2> 784604 T2147 C820 P34984 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C821 name=collection1 org.apache.solr.core.SolrCore@12963a4 url=http://127.0.0.1:36971/collection1 node=127.0.0.1:36971_ C821_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:36971_, base_url=http://127.0.0.1:36971}
[junit4:junit4] 2> 784604 T2132 C821 P36971 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 784614 T2166 C817 P56116 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@e726b1; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@e726b1; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 784614 T2166 C817 P56116 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 784615 T2166 C817 P56116 oass.SolrIndexSearcher.<init> Opening Searcher@6ff61d main
[junit4:junit4] 2> 784616 T2166 C817 P56116 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 784616 T2177 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6ff61d main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 784617 T2166 C817 P56116 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 21
[junit4:junit4] 2> 784624 T2115 C818 P52153 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 784624 T2115 C818 P52153 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 784625 T2115 C818 P52153 oass.SolrIndexSearcher.<init> Opening Searcher@1822da1 main
[junit4:junit4] 2> 784625 T2115 C818 P52153 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 784626 T2123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1822da1 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 784627 T2115 C818 P52153 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 31
[junit4:junit4] 2> 784654 T2147 C820 P34984 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@17710f8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@17710f8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 784654 T2147 C820 P34984 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 784655 T2132 C821 P36971 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@13bca46; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@13bca46; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 784655 T2147 C820 P34984 oass.SolrIndexSearcher.<init> Opening Searcher@91bede main
[junit4:junit4] 2> 784655 T2132 C821 P36971 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 784656 T2147 C820 P34984 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 784656 T2132 C821 P36971 oass.SolrIndexSearcher.<init> Opening Searcher@1cc84ff main
[junit4:junit4] 2> 784657 T2132 C821 P36971 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 784657 T2156 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@91bede main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 784658 T2147 C820 P34984 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 54
[junit4:junit4] 2> 784658 T2139 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1cc84ff main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 784659 T2132 C821 P36971 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 55
[junit4:junit4] 2> 784659 T2165 C817 P56116 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 66
[junit4:junit4] 2> 784660 T2079 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 784662 T2117 C818 P52153 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> 784663 T2133 C821 P36971 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> 784665 T2149 C820 P34984 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> 784666 T2164 C817 P56116 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> 786669 T2097 C819 P59807 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438522950451986432)} 0 1
[junit4:junit4] 2> 786675 T2131 C821 P36971 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438522950456180736&update.from=http://127.0.0.1:52153/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438522950456180736)} 0 0
[junit4:junit4] 2> 786675 T2149 C820 P34984 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438522950456180736&update.from=http://127.0.0.1:52153/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438522950456180736)} 0 0
[junit4:junit4] 2> 786676 T2164 C817 P56116 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438522950456180736&update.from=http://127.0.0.1:52153/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438522950456180736)} 0 1
[junit4:junit4] 2> 786676 T2116 C818 P52153 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438522950456180736)} 0 4
[junit4:junit4] 2> 786677 T2165 C817 P56116 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:*} 0 6
[junit4:junit4] 2> 786680 T2095 C819 P59807 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1438522950463520768)]} 0 1
[junit4:junit4] 2> 786685 T2132 C821 P36971 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52153/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438522950466666496)]} 0 1
[junit4:junit4] 2> 786685 T2150 C820 P34984 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52153/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438522950466666496)]} 0 1
[junit4:junit4] 2> 786685 T2167 C817 P56116 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52153/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438522950466666496)]} 0 1
[junit4:junit4] 2> 786686 T2117 C818 P52153 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1438522950466666496)]} 0 5
[junit4:junit4] 2> 786689 T2096 C819 P59807 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1438522950472957952)]} 0 1
[junit4:junit4] 2> 786694 T2130 C821 P36971 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52153/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438522950476103680)]} 0 1
[junit4:junit4] 2> 786694 T2147 C820 P34984 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52153/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438522950476103680)]} 0 1
[junit4:junit4] 2> 786695 T2166 C817 P56116 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52153/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438522950476103680)]} 0 1
[junit4:junit4] 2> 786695 T2114 C818 P52153 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1438522950476103680)]} 0 4
[junit4:junit4] 2> 786698 T2094 C819 P59807 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1438522950483443712)]} 0 1
[junit4:junit4] 2> 786701 T2115 C818 P52153 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:36971/collection1/]
[junit4:junit4] 2> 786701 T2115 C818 P52153 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:36971/collection1/ against:[http://127.0.0.1:36971/collection1/] result:true
[junit4:junit4] 2> 786701 T2115 C818 P52153 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:34984/collection1/ against:[http://127.0.0.1:36971/collection1/] result:false
[junit4:junit4] 2> 786702 T2115 C818 P52153 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:56116/collection1/ against:[http://127.0.0.1:36971/collection1/] result:false
[junit4:junit4] 2> 786705 T2148 C820 P34984 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52153/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:36971/collection1/&wt=javabin&version=2} {add=[2 (1438522950487638016)]} 0 1
[junit4:junit4] 2> 786705 T2164 C817 P56116 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52153/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:36971/collection1/&wt=javabin&version=2} {add=[2 (1438522950487638016)]} 0 1
[junit4:junit4] 2> 786706 T2115 C818 P52153 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:36971/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:36971/collection1/&wt=javabin&version=2} {add=[2 (1438522950487638016)]} 0 5
[junit4:junit4] 2> 786706 T2133 C821 P36971 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:36971/collection1/&wt=javabin&version=2} {add=[2]} 0 7
[junit4:junit4] 2> 786709 T2097 C819 P59807 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1438522950493929472)]} 0 1
[junit4:junit4] 2> 786711 T2116 C818 P52153 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:34984/collection1/, http://127.0.0.1:36971/collection1/]
[junit4:junit4] 2> 786712 T2116 C818 P52153 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:36971/collection1/ against:[http://127.0.0.1:34984/collection1/, http://127.0.0.1:36971/collection1/] result:true
[junit4:junit4] 2> 786712 T2116 C818 P52153 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:34984/collection1/ against:[http://127.0.0.1:34984/collection1/, http://127.0.0.1:36971/collection1/] result:true
[junit4:junit4] 2> 786712 T2116 C818 P52153 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:56116/collection1/ against:[http://127.0.0.1:34984/collection1/, http://127.0.0.1:36971/collection1/] result:false
[junit4:junit4] 2> 786715 T2165 C817 P56116 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:52153/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:36971/collection1/&wt=javabin&version=2} {add=[3 (1438522950499172352)]} 0 0
[junit4:junit4] 2> 786716 T2116 C818 P52153 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:36971/collection1/&test.distrib.skip.servers=http://127.0.0.1:34984/collection1/&wt=javabin&version=2} {add=[3 (1438522950499172352)]} 0 5
[junit4:junit4] 2> 786718 T2095 C819 P59807 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 786734 T2095 C819 P59807 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@127e093; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@127e093; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 786734 T2095 C819 P59807 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 786736 T2095 C819 P59807 oass.SolrIndexSearcher.<init> Opening Searcher@108c9c9 main
[junit4:junit4] 2> 786737 T2095 C819 P59807 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 786737 T2105 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@108c9c9 main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):C4)}
[junit4:junit4] 2> 786738 T2095 C819 P59807 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 20
[junit4:junit4] 2> 786740 T2167 C817 P56116 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:52153/collection1/, StdNode: http://127.0.0.1:36971/collection1/, StdNode: http://127.0.0.1:34984/collection1/, StdNode: http://127.0.0.1:56116/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 786742 T2166 C817 P56116 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 786742 T2131 C821 P36971 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 786742 T2149 C820 P34984 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 786742 T2117 C818 P52153 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 786784 T2131 C821 P36971 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@13bca46; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@13bca46; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 786784 T2149 C820 P34984 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@17710f8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@17710f8; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 786785 T2149 C820 P34984 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 786784 T2166 C817 P56116 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@e726b1; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@e726b1; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 786786 T2166 C817 P56116 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 786784 T2117 C818 P52153 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=5
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 786787 T2117 C818 P52153 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 786784 T2131 C821 P36971 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 786787 T2149 C820 P34984 oass.SolrIndexSearcher.<init> Opening Searcher@13f7559 main
[junit4:junit4] 2> 786788 T2166 C817 P56116 oass.SolrIndexSearcher.<init> Opening Searcher@1e92e2d main
[junit4:junit4] 2> 786788 T2149 C820 P34984 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 786788 T2166 C817 P56116 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 786789 T2117 C818 P52153 oass.SolrIndexSearcher.<init> Opening Searcher@2f7342 main
[junit4:junit4] 2> 786789 T2156 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@13f7559 main{StandardDirectoryReader(segments_5:3:nrt _0(4.4):C3)}
[junit4:junit4] 2> 786789 T2131 C821 P36971 oass.SolrIndexSearcher.<init> Opening Searcher@4b4119 main
[junit4:junit4] 2> 786788 T2177 oasc.JmxMonitoredMap.put WARN Failed to register info bean: searcher javax.management.InstanceAlreadyExistsException: solr/collection1:type=searcher,id=org.apache.solr.search.SolrIndexSearcher
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:437)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1898)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:966)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:900)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:324)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:522)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:140)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4] 2> at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:298)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1846)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.access$000(SolrCore.java:135)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1723)
[junit4:junit4] 2> at java.util.concurrent.FutureTask$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> 786790 T2123 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2f7342 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):C4)}
[junit4:junit4] 2> 786790 T2149 C820 P34984 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> 786790 T2131 C821 P36971 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 786789 T2117 C818 P52153 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 786791 T2139 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4b4119 main{StandardDirectoryReader(segments_4:3:nrt _0(4.4):C2)}
[junit4:junit4] 2> 786791 T2177 oasc.JmxMonitoredMap.put WARN Failed to register info bean: fieldValueCache javax.management.InstanceNotFoundException: solr/collection1:type=fieldValueCache,id=org.apache.solr.search.FastLRUCache
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.getMBean(DefaultMBeanServerInterceptor.java:1095)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.exclusiveUnregisterMBean(DefaultMBeanServerInterceptor.java:427)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.unregisterMBean(DefaultMBeanServerInterceptor.java:415)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.unregisterMBean(JmxMBeanServer.java:546)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:138)
[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> 786792 T2131 C821 P36971 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 50
[junit4:junit4] 2> 786791 T2117 C818 P52153 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 49
[junit4:junit4] 2> 786792 T2177 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1e92e2d main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):C4)}
[junit4:junit4] 2> 786794 T2166 C817 P56116 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> 786794 T2167 C817 P56116 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 54
[junit4:junit4] 2> 786794 T2079 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 786795 T2079 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 786796 T2079 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 786798 T2114 C818 P52153 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> 786800 T2132 C821 P36971 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> 786801 T2150 C820 P34984 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=3 status=0 QTime=0
[junit4:junit4] 2> 786803 T2164 C817 P56116 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> 786805 T2079 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 786809 T2148 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2
[junit4:junit4] 2> 786810 T2148 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 786813 T2115 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 786813 T2115 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:52153/collection1/
[junit4:junit4] 2> 786813 T2115 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52153 START replicas=[http://127.0.0.1:36971/collection1/, http://127.0.0.1:34984/collection1/, http://127.0.0.1:56116/collection1/] nUpdates=100
[junit4:junit4] 2> 786815 T2149 C820 P34984 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> 786815 T2130 C821 P36971 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> 786815 T2115 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:52153 Received 4 versions from 127.0.0.1:34984/collection1/
[junit4:junit4] 2> 786815 T2165 C817 P56116 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> 786816 T2115 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:52153 Our versions are newer. ourLowThreshold=1438522950456180736 otherHigh=1438522950487638016
[junit4:junit4] 2> 786816 T2115 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:52153 Received 3 versions from 127.0.0.1:36971/collection1/
[junit4:junit4] 2> 786816 T2115 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:52153 Our versions are newer. ourLowThreshold=1438522950456180736 otherHigh=1438522950476103680
[junit4:junit4] 2> 786817 T2115 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:52153 Received 5 versions from 127.0.0.1:56116/collection1/
[junit4:junit4] 2> 786817 T2115 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:52153 Our versions are newer. ourLowThreshold=1438522950456180736 otherHigh=1438522950487638016
[junit4:junit4] 2> 786817 T2115 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:52153 DONE. sync succeeded
[junit4:junit4] 2> 786818 T2115 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 786818 T2115 oasc.SyncStrategy.syncToMe http://127.0.0.1:52153/collection1/: try and ask http://127.0.0.1:36971/collection1/ to sync
[junit4:junit4] 2> 786818 T2115 oasc.SyncStrategy.syncToMe http://127.0.0.1:52153/collection1/: try and ask http://127.0.0.1:34984/collection1/ to sync
[junit4:junit4] 2> 786819 T2115 oasc.SyncStrategy.syncToMe http://127.0.0.1:52153/collection1/: try and ask http://127.0.0.1:56116/collection1/ to sync
[junit4:junit4] 2> 786819 T2133 C821 P36971 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:36971 START replicas=[http://127.0.0.1:52153/collection1/] nUpdates=100
[junit4:junit4] 2> 786820 T2147 C820 P34984 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34984 START replicas=[http://127.0.0.1:52153/collection1/] nUpdates=100
[junit4:junit4] 2> 786820 T2166 C817 P56116 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56116 START replicas=[http://127.0.0.1:52153/collection1/] nUpdates=100
[junit4:junit4] 2> 786821 T2116 C818 P52153 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> 786821 T2117 C818 P52153 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> 786821 T2147 C820 P34984 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:34984 Received 5 versions from 127.0.0.1:52153/collection1/
[junit4:junit4] 2> 786821 T2166 C817 P56116 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:56116 Received 5 versions from 127.0.0.1:52153/collection1/
[junit4:junit4] 2> 786821 T2114 C818 P52153 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> 786822 T2166 C817 P56116 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:56116 Our versions are newer. ourLowThreshold=1438522950456180736 otherHigh=1438522950487638016
[junit4:junit4] 2> 786822 T2147 C820 P34984 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:34984 Requesting updates from 127.0.0.1:52153/collection1/n=1 versions=[1438522950499172352]
[junit4:junit4] 2> 786822 T2166 C817 P56116 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56116 DONE. sync succeeded
[junit4:junit4] 2> 786822 T2133 C821 P36971 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:36971 Received 5 versions from 127.0.0.1:52153/collection1/
[junit4:junit4] 2> 786823 T2166 C817 P56116 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:52153/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=3
[junit4:junit4] 2> 786823 T2133 C821 P36971 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:36971 Requesting updates from 127.0.0.1:52153/collection1/n=2 versions=[1438522950499172352, 1438522950487638016]
[junit4:junit4] 2> 786824 T2115 oasc.SyncStrategy.syncToMe http://127.0.0.1:52153/collection1/: sync completed with http://127.0.0.1:56116/collection1/
[junit4:junit4] 2> 786824 T2116 C818 P52153 oasc.SolrCore.execute [collection1] webapp= path=/get params={distrib=false&getUpdates=1438522950499172352&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 786826 T2117 C818 P52153 oasc.SolrCore.execute [collection1] webapp= path=/get params={distrib=false&getUpdates=1438522950499172352,1438522950487638016&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 786826 T2147 C820 P34984 oasup.LogUpdateProcessor.finish [collection1] {add=[3 (1438522950499172352)]} 0 1
[junit4:junit4] 2> 786827 T2147 C820 P34984 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:34984 DONE. sync succeeded
[junit4:junit4] 2> 786827 T2147 C820 P34984 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:52153/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=7
[junit4:junit4] 2> 786827 T2115 oasc.SyncStrategy.syncToMe http://127.0.0.1:52153/collection1/: sync completed with http://127.0.0.1:34984/collection1/
[junit4:junit4] 2> 786828 T2133 C821 P36971 oasup.LogUpdateProcessor.finish [collection1] {add=[2 (1438522950487638016), 3 (1438522950499172352)]} 0 2
[junit4:junit4] 2> 786829 T2133 C821 P36971 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:36971 DONE. sync succeeded
[junit4:junit4] 2> 786829 T2133 C821 P36971 oasc.SolrCore.execute [collection1] webapp= path=/get params={sync=http://127.0.0.1:52153/collection1/&getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=10
[junit4:junit4] 2> 786829 T2115 oasc.SyncStrategy.syncToMe http://127.0.0.1:52153/collection1/: sync completed with http://127.0.0.1:36971/collection1/
[junit4:junit4] 2> 786830 T2115 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=17
[junit4:junit4] 2> 786830 T2148 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/collections params={shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2} status=0 QTime=22
[junit4:junit4] 2> 786831 T2079 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 786831 T2079 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 786832 T2079 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 786832 T2079 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 786834 T2096 C819 P59807 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 786884 T2096 C819 P59807 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@127e093; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@127e093; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 786884 T2096 C819 P59807 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 786885 T2096 C819 P59807 oass.SolrIndexSearcher.<init> Opening Searcher@801c43 main
[junit4:junit4] 2> 786885 T2096 C819 P59807 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 786886 T2105 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@801c43 main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):C4)}
[junit4:junit4] 2> 786887 T2096 C819 P59807 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 53
[junit4:junit4] 2> 786889 T2167 C817 P56116 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:52153/collection1/, StdNode: http://127.0.0.1:36971/collection1/, StdNode: http://127.0.0.1:34984/collection1/, StdNode: http://127.0.0.1:56116/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 786891 T2114 C818 P52153 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 786891 T2131 C821 P36971 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 786891 T2150 C820 P34984 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 786891 T2164 C817 P56116 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 786914 T2114 C818 P52153 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=5
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J1/org.apache.solr.cloud.SyncSliceTest-1371882369719/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@15aaf58; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generati
[...truncated too long message...]
"collection":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:34984_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:34984"},
[junit4:junit4] 1> "127.0.0.1:56116__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:56116_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:56116",
[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:59807__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:59807_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:59807",
[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:34984_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:52153_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:59807_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:56116_ (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/89907682982101006-127.0.0.1:52153__collection1-n_0000000004 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89907682982101002-127.0.0.1:34984__collection1-n_0000000005 (0)
[junit4:junit4] 1> /solr/collections/collection1/leader_elect/shard1/election/89907682982101004-127.0.0.1:56116__collection1-n_0000000003 (0)
[junit4:junit4] 1> /solr/collections/collection1/leaders (1)
[junit4:junit4] 1> /solr/collections/collection1/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "node_name":"127.0.0.1:56116_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:56116"}
[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/89907682982100995-127.0.0.1:59807__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:59807_",
[junit4:junit4] 1> "base_url":"http://127.0.0.1:59807"}
[junit4:junit4] 1> /solr/overseer_elect (2)
[junit4:junit4] 1> /solr/overseer_elect/election (4)
[junit4:junit4] 1> /solr/overseer_elect/election/89907682982101006-127.0.0.1:52153_-n_0000000005 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89907682982101004-127.0.0.1:56116_-n_0000000004 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89907682982101002-127.0.0.1:34984_-n_0000000003 (0)
[junit4:junit4] 1> /solr/overseer_elect/election/89907682982100995-127.0.0.1:59807_-n_0000000000 (0)
[junit4:junit4] 1> /solr/overseer_elect/leader (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {"id":"89907682982100995-127.0.0.1:59807_-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=9CCC48FAA3121E43 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=de_DE -Dtests.timezone=Atlantic/Faeroe -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 108s J1 | SyncSliceTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:52153/collection1lastClient and got 255 from http://127.0.0.1:34984/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([9CCC48FAA3121E43:1D2AC6E2D44D7E7F]: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> 873212 T2079 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 108249 T2078 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 1 leaked thread(s).
[junit4:junit4] 2> NOTE: test params are: codec=Asserting, sim=DefaultSimilarity, locale=de_DE, timezone=Atlantic/Faeroe
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic i386/Oracle Corporation 1.7.0_25 (32-bit)/cpus=8,threads=1,free=91846288,total=253820928
[junit4:junit4] 2> NOTE: All tests run in this JVM: [IndexBasedSpellCheckerTest, TestLMJelinekMercerSimilarityFactory, TermVectorComponentDistributedTest, PingRequestHandlerTest, TestShardHandlerFactory, TestStressReorder, DocValuesMultiTest, SolrPluginUtilsTest, DirectUpdateHandlerTest, TestLazyCores, TestStressLucene, TestRangeQuery, TestAddFieldRealTimeGet, ZkNodePropsTest, RequestHandlersTest, TestDefaultSimilarityFactory, TestFiltering, TestHashPartitioner, TestCollationField, SuggesterTSTTest, UpdateParamsTest, UniqFieldsUpdateProcessorFactoryTest, TestFoldingMultitermQuery, XsltUpdateRequestHandlerTest, TestAnalyzedSuggestions, DirectSolrSpellCheckerTest, TestBM25SimilarityFactory, TestRTGBase, BasicZkTest, URLClassifyProcessorTest, TestPropInject, DefaultValueUpdateProcessorTest, TestCodecSupport, XmlUpdateRequestHandlerTest, CurrencyFieldOpenExchangeTest, TestDynamicFieldCollectionResource, CoreContainerCoreInitFailuresTest, SuggesterWFSTTest, TestBinaryResponseWriter, TestSolrJ, TestJmxIntegration, LeaderElectionIntegrationTest, TestBinaryField, SimplePostToolTest, TestSolrXml, TestManagedSchemaFieldResource, TestFieldTypeCollectionResource, ChaosMonkeySafeLeaderTest, DisMaxRequestHandlerTest, TestWordDelimiterFilterFactory, FullSolrCloudDistribCmdsTest, TestSuggestSpellingConverter, DateMathParserTest, TestLuceneMatchVersion, StandardRequestHandlerTest, TestCSVLoader, JSONWriterTest, NotRequiredUniqueKeyTest, HighlighterConfigTest, TestAtomicUpdateErrorCases, ClusterStateTest, DocumentAnalysisRequestHandlerTest, TestZkChroot, TestSolrXMLSerializer, TestMaxScoreQueryParser, ShardRoutingCustomTest, TestReload, CopyFieldTest, HighlighterTest, BadIndexSchemaTest, BasicDistributedZk2Test, SolrRequestParserTest, UnloadDistributedZkTest, SyncSliceTest]
[junit4:junit4] Completed on J1 in 108.53s, 1 test, 1 failure <<< FAILURES!
[...truncated 460 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, 1255 tests, 1 failure, 13 ignored (7 assumptions)
Total time: 38 minutes 30 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_25 -client -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure