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/17 23:24:54 UTC
[JENKINS] Lucene-Solr-4.x-Linux (32bit/ibm-j9-jdk7) - Build # 6110
- Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Linux/6110/
Java: 32bit/ibm-j9-jdk7 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}
2 tests failed.
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:47721/collection1lastClient and got 250 from http://127.0.0.1:38598/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:47721/collection1lastClient and got 250 from http://127.0.0.1:38598/collection1
at __randomizedtesting.SeedInfo.seed([7F8D4AFFE52C4384:FE6BC4E7927323B8]: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:88)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
at java.lang.reflect.Method.invoke(Method.java:613)
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:780)
FAILED: org.apache.solr.cloud.BasicDistributedZk2Test.testDistribSearch
Error Message:
Server at http://127.0.0.1:38100/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:38100/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
at __randomizedtesting.SeedInfo.seed([7F8D4AFFE52C4384:FE6BC4E7927323B8]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:198)
at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:90)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:88)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:55)
at java.lang.reflect.Method.invoke(Method.java:613)
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:780)
Build Log:
[...truncated 9356 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 13573 T45 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 13582 T45 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./solrtest-SyncSliceTest-1371503042293
[junit4:junit4] 2> 13585 T45 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 13607 T46 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 13688 T45 oasc.ZkTestServer.run start zk server on port:51362
[junit4:junit4] 2> 13794 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 14104 T54 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3b87a6ed name:ZooKeeperConnection Watcher:127.0.0.1:51362 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 14105 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 14106 T45 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 14134 T47 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f53f39f820000, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:780)
[junit4:junit4] 2>
[junit4:junit4] 2> 14136 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 14142 T56 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@fccd86e0 name:ZooKeeperConnection Watcher:127.0.0.1:51362/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 14142 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 14146 T45 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 14154 T45 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 14159 T45 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 14163 T45 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 14168 T45 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> 14175 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 14222 T45 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> 14223 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 14231 T45 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> 14235 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 14242 T45 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> 14243 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 14247 T45 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> 14248 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 14253 T45 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> 14254 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 14259 T45 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> 14260 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 14265 T45 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> 14266 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 14270 T45 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> 14271 T45 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 14436 T45 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 14502 T45 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:33883
[junit4:junit4] 2> 14644 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 14645 T45 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 14645 T45 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371503042987
[junit4:junit4] 2> 14646 T45 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371503042987/solr.xml
[junit4:junit4] 2> 14647 T45 oasc.CoreContainer.<init> New CoreContainer -733408015
[junit4:junit4] 2> 14647 T45 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371503042987/'
[junit4:junit4] 2> 14648 T45 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371503042987/'
[junit4:junit4] 2> 14773 T45 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 14774 T45 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 14775 T45 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 14775 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 14776 T45 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 14777 T45 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 14777 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 14778 T45 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 14779 T45 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 14787 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 15246 T45 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 15247 T45 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51362/solr
[junit4:junit4] 2> 15253 T45 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 15254 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 15258 T69 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@ba9e0bb name:ZooKeeperConnection Watcher:127.0.0.1:51362 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 15259 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 15262 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 15300 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 15302 T71 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@822232a0 name:ZooKeeperConnection Watcher:127.0.0.1:51362/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 15302 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 15307 T45 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 15315 T45 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 15322 T45 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 15325 T45 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:33883_
[junit4:junit4] 2> 15328 T45 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:33883_
[junit4:junit4] 2> 15333 T45 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 15347 T45 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 15351 T45 oasc.Overseer.start Overseer (id=89882823388954627-127.0.0.1:33883_-n_0000000000) starting
[junit4:junit4] 2> 15367 T45 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 15376 T73 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 15377 T45 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 15384 T45 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 15389 T45 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 15398 T72 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 15411 T74 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 15411 T74 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 16904 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 16905 T72 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:33883",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:33883_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 16905 T72 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 16909 T72 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 16917 T71 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> 17414 T74 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371503042987/collection1
[junit4:junit4] 2> 17414 T74 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 17416 T74 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 17416 T74 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 17419 T74 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371503042987/collection1/'
[junit4:junit4] 2> 17420 T74 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1371503042987/collection1/lib/README' to classloader
[junit4:junit4] 2> 17420 T74 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1371503042987/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 17462 T74 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 17509 T74 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 17516 T74 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 17526 T74 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 18147 T74 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 18154 T74 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 18157 T74 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 18198 T74 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 18204 T74 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 18210 T74 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 18213 T74 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 18213 T74 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 18214 T74 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 18216 T74 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 18216 T74 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 18217 T74 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 18220 T74 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-controljetty-1371503042987/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371503042293/control/data/
[junit4:junit4] 2> 18220 T74 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a162f151
[junit4:junit4] 2> 18223 T74 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 18224 T74 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/control/data
[junit4:junit4] 2> 18224 T74 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371503042293/control/data/index/
[junit4:junit4] 2> 18225 T74 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371503042293/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 18225 T74 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/control/data/index
[junit4:junit4] 2> 18320 T74 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@f557b435; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 18321 T74 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 18331 T74 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 18332 T74 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 18333 T74 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 18336 T74 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 18338 T74 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 18339 T74 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 18339 T74 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 18341 T74 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 18342 T74 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 18344 T74 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 18348 T74 oass.SolrIndexSearcher.<init> Opening Searcher@543d9512 main
[junit4:junit4] 2> 18349 T74 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 18350 T74 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 18377 T75 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@543d9512 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 18384 T74 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 18385 T74 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:33883 collection:control_collection shard:shard1
[junit4:junit4] 2> 18388 T74 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=10000&maxConnectionsPerHost=20&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 18413 T74 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 18432 T74 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 18437 T74 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 18438 T74 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 18439 T74 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:33883/collection1/
[junit4:junit4] 2> 18439 T74 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 18440 T74 oasc.SyncStrategy.syncToMe http://127.0.0.1:33883/collection1/ has no replicas
[junit4:junit4] 2> 18441 T74 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:33883/collection1/
[junit4:junit4] 2> 18442 T74 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 19928 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 19950 T71 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> 20007 T74 oasc.ZkController.register We are http://127.0.0.1:33883/collection1/ and leader is http://127.0.0.1:33883/collection1/
[junit4:junit4] 2> 20007 T74 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:33883
[junit4:junit4] 2> 20008 T74 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 20008 T74 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 20009 T74 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 20012 T74 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 20015 T45 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 20015 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 20025 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 20046 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 20049 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 20051 T78 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3c422912 name:ZooKeeperConnection Watcher:127.0.0.1:51362/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 20053 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 20055 T45 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 20064 T45 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 20448 T45 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 20452 T45 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:47721
[junit4:junit4] 2> 20453 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 20454 T45 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 20455 T45 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371503048774
[junit4:junit4] 2> 20456 T45 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371503048774/solr.xml
[junit4:junit4] 2> 20457 T45 oasc.CoreContainer.<init> New CoreContainer 578789525
[junit4:junit4] 2> 20458 T45 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371503048774/'
[junit4:junit4] 2> 20460 T45 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371503048774/'
[junit4:junit4] 2> 20656 T45 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 20659 T45 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 20662 T45 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 20664 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 20666 T45 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 20669 T45 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 20671 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 20673 T45 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 20676 T45 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 20681 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 20723 T45 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 20727 T45 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51362/solr
[junit4:junit4] 2> 20729 T45 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 20734 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 20751 T89 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5446ffd2 name:ZooKeeperConnection Watcher:127.0.0.1:51362 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 20751 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 20756 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 20767 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 20780 T91 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8621a01 name:ZooKeeperConnection Watcher:127.0.0.1:51362/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 20781 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 20796 T45 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 21463 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 21466 T72 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:33883",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:33883__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:33883_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 21477 T78 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> 21478 T91 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> 21481 T71 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> 21803 T45 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47721_
[junit4:junit4] 2> 21812 T45 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47721_
[junit4:junit4] 2> 21826 T71 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 21827 T78 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 21828 T78 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> 21834 T71 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 21837 T91 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 21837 T91 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> 21857 T92 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 21857 T92 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 22994 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 22999 T72 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47721",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:47721_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 23000 T72 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 23001 T72 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 23022 T91 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> 23022 T78 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> 23028 T71 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> 23904 T92 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371503048774/collection1
[junit4:junit4] 2> 23904 T92 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 23908 T92 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 23908 T92 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 23911 T92 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371503048774/collection1/'
[junit4:junit4] 2> 23912 T92 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1371503048774/collection1/lib/README' to classloader
[junit4:junit4] 2> 23914 T92 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1371503048774/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 24064 T92 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 24204 T92 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 24216 T92 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 24271 T92 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 26165 T92 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 26206 T92 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 26229 T92 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 26464 T92 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 26501 T92 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 26549 T92 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 26559 T92 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 26560 T92 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 26561 T92 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 26569 T92 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 26570 T92 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 26571 T92 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 26575 T92 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty1-1371503048774/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/
[junit4:junit4] 2> 26577 T92 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a162f151
[junit4:junit4] 2> 26579 T92 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 26580 T92 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1
[junit4:junit4] 2> 26581 T92 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index/
[junit4:junit4] 2> 26582 T92 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 26582 T92 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index
[junit4:junit4] 2> 26639 T92 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 26639 T92 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 26723 T92 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 26725 T92 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 26728 T92 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 26747 T92 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 26750 T92 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 26754 T92 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 26763 T92 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 26790 T92 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 26811 T92 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 26814 T92 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 26830 T92 oass.SolrIndexSearcher.<init> Opening Searcher@e219ddcd main
[junit4:junit4] 2> 26831 T92 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 26831 T92 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 27057 T93 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e219ddcd main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 27134 T92 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 27136 T92 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47721 collection:collection1 shard:shard1
[junit4:junit4] 2> 27143 T92 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 27179 T92 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 27229 T92 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 27230 T92 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 27230 T92 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:47721/collection1/
[junit4:junit4] 2> 27231 T92 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 27231 T92 oasc.SyncStrategy.syncToMe http://127.0.0.1:47721/collection1/ has no replicas
[junit4:junit4] 2> 27233 T92 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:47721/collection1/
[junit4:junit4] 2> 27233 T92 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 27615 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 27640 T78 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> 27641 T91 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> 27648 T71 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> 27657 T92 oasc.ZkController.register We are http://127.0.0.1:47721/collection1/ and leader is http://127.0.0.1:47721/collection1/
[junit4:junit4] 2> 27658 T92 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47721
[junit4:junit4] 2> 27658 T92 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 27658 T92 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 27659 T92 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 27662 T92 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 27666 T45 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 27667 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 27668 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 28266 T45 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 28279 T45 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:46709
[junit4:junit4] 2> 28281 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 28282 T45 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 28288 T45 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371503056412
[junit4:junit4] 2> 28290 T45 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371503056412/solr.xml
[junit4:junit4] 2> 28293 T45 oasc.CoreContainer.<init> New CoreContainer 160203099
[junit4:junit4] 2> 28295 T45 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371503056412/'
[junit4:junit4] 2> 28297 T45 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371503056412/'
[junit4:junit4] 2> 28759 T45 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 28761 T45 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 28762 T45 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 28769 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 28784 T45 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 28787 T45 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 28789 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 28790 T45 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 28812 T45 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 28813 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 28868 T45 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 28876 T45 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51362/solr
[junit4:junit4] 2> 28882 T45 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 28894 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 28929 T109 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@c1d9508b name:ZooKeeperConnection Watcher:127.0.0.1:51362 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 28944 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 28951 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 29005 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 29025 T111 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@cb073096 name:ZooKeeperConnection Watcher:127.0.0.1:51362/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 29026 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 29041 T45 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 29184 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 29189 T72 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47721",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:47721__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:47721_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 29220 T78 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> 29220 T111 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> 29220 T91 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> 29228 T71 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> 30050 T45 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46709_
[junit4:junit4] 2> 30053 T45 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46709_
[junit4:junit4] 2> 30060 T71 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> 30063 T91 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 30063 T91 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> 30066 T78 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 30067 T78 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> 30074 T111 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> 30077 T71 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 30089 T111 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 30166 T112 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 30166 T112 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 30747 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 30750 T72 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46709",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46709_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 30750 T72 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 30751 T72 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 30765 T111 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> 30765 T91 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> 30765 T71 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> 30765 T78 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> 31171 T112 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371503056412/collection1
[junit4:junit4] 2> 31171 T112 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 31173 T112 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 31173 T112 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 31177 T112 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371503056412/collection1/'
[junit4:junit4] 2> 31178 T112 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1371503056412/collection1/lib/README' to classloader
[junit4:junit4] 2> 31179 T112 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1371503056412/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 31371 T112 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 31645 T112 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 31664 T112 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 31772 T112 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 34079 T112 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 34099 T112 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 34106 T112 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 34374 T112 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 34402 T112 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 34419 T112 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 34450 T112 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 34453 T112 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 34457 T112 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 34465 T112 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 34465 T112 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 34466 T112 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 34467 T112 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty2-1371503056412/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/
[junit4:junit4] 2> 34472 T112 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a162f151
[junit4:junit4] 2> 34483 T112 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 34484 T112 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2
[junit4:junit4] 2> 34484 T112 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index/
[junit4:junit4] 2> 34485 T112 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 34488 T112 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index
[junit4:junit4] 2> 34510 T112 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b9dfbefb; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 34510 T112 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 34529 T112 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 34530 T112 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 34541 T112 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 34549 T112 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 34562 T112 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 34564 T112 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 34566 T112 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 34577 T112 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 34584 T112 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 34594 T112 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 34629 T112 oass.SolrIndexSearcher.<init> Opening Searcher@af004e74 main
[junit4:junit4] 2> 34634 T112 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 34643 T112 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 34786 T113 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@af004e74 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 34854 T112 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 34855 T112 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46709 collection:collection1 shard:shard1
[junit4:junit4] 2> 34880 T112 oasc.ZkController.register We are http://127.0.0.1:46709/collection1/ and leader is http://127.0.0.1:47721/collection1/
[junit4:junit4] 2> 34881 T112 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46709
[junit4:junit4] 2> 34881 T112 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 34884 T112 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> 34922 T112 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C14 name=collection1 org.apache.solr.core.SolrCore@29beb3a url=http://127.0.0.1:46709/collection1 node=127.0.0.1:46709_ C14_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:46709, state=down, node_name=127.0.0.1:46709_, collection=collection1, core=collection1}
[junit4:junit4] 2> 34938 T114 C14 P46709 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 34943 T114 C14 P46709 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 34944 T45 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 34946 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 34947 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 34945 T114 C14 P46709 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 34949 T114 C14 P46709 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 34955 T114 C14 P46709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 35335 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 35338 T72 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46709",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:46709__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:46709_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 35347 T111 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> 35347 T91 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> 35348 T71 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> 35348 T78 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> 35664 T45 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 35702 T45 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:38598
[junit4:junit4] 2> 35712 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 35713 T45 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 35714 T45 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371503063703
[junit4:junit4] 2> 35740 T45 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371503063703/solr.xml
[junit4:junit4] 2> 35743 T45 oasc.CoreContainer.<init> New CoreContainer 136813307
[junit4:junit4] 2> 35748 T45 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371503063703/'
[junit4:junit4] 2> 35774 T45 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371503063703/'
[junit4:junit4] 2> 36036 T85 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:46709__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 36037 T85 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:46709__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 0 seconds.
[junit4:junit4] 2> 36038 T85 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=127.0.0.1:46709__collection1&wt=javabin&nodeName=127.0.0.1:46709_&core=collection1} status=0 QTime=4
[junit4:junit4] 2> 36052 T45 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 36053 T45 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 36054 T45 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 36056 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 36057 T45 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 36058 T45 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 36058 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 36062 T45 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 36064 T45 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 36067 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 36090 T45 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 36094 T45 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51362/solr
[junit4:junit4] 2> 36097 T45 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 36100 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 36117 T126 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@bed5609c name:ZooKeeperConnection Watcher:127.0.0.1:51362 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 36118 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 36129 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 36167 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 36172 T128 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@29734eb2 name:ZooKeeperConnection Watcher:127.0.0.1:51362/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 36174 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 36211 T45 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 37226 T45 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:38598_
[junit4:junit4] 2> 37229 T45 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:38598_
[junit4:junit4] 2> 37233 T71 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> 37234 T111 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> 37236 T91 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 37237 T91 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> 37238 T78 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 37239 T78 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> 37243 T71 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 37248 T111 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 37250 T128 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 37284 T129 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 37285 T129 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> ASYNC NEW_CORE C15 name=collection1 org.apache.solr.core.SolrCore@29beb3a url=http://127.0.0.1:46709/collection1 node=127.0.0.1:46709_ C15_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:46709, state=recovering, node_name=127.0.0.1:46709_, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4] 2> 38062 T114 C15 P46709 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:47721/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 38065 T114 C15 P46709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&connTimeout=30000&socketTimeout=30000&retry=false
[junit4:junit4] 2> 38132 T114 C15 P46709 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:46709 START replicas=[http://127.0.0.1:47721/collection1/] nUpdates=100
[junit4:junit4] 2> 38147 T114 C15 P46709 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 38152 T114 C15 P46709 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 38153 T114 C15 P46709 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 38154 T114 C15 P46709 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 38155 T114 C15 P46709 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 38157 T114 C15 P46709 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:47721/collection1/. core=collection1
[junit4:junit4] 2> 38157 T114 C15 P46709 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C16 name=collection1 org.apache.solr.core.SolrCore@6ca79287 url=http://127.0.0.1:47721/collection1 node=127.0.0.1:47721_ C16_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:47721, state=active, node_name=127.0.0.1:47721_, collection=collection1, shard=shard1, core=collection1, leader=true}
[junit4:junit4] 2> 38203 T85 C16 P47721 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=2
[junit4:junit4] 2> 38245 T84 C16 P47721 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 38249 T84 C16 P47721 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 38250 T84 C16 P47721 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 38271 T84 C16 P47721 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 38272 T84 C16 P47721 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 38273 T84 C16 P47721 oass.SolrIndexSearcher.<init> Opening Searcher@34d726f4 realtime
[junit4:junit4] 2> 38274 T84 C16 P47721 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 38282 T84 C16 P47721 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 44
[junit4:junit4] 2> 38308 T114 C15 P46709 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 38312 T114 C15 P46709 oascsi.HttpClientUtil.createClient Creating new http client, config:connTimeout=5000&socketTimeout=20000&allowCompression=false&maxConnections=10000&maxConnectionsPerHost=10000
[junit4:junit4] 2> 38352 T114 C15 P46709 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 38373 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 38377 T72 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38598",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:38598_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 38377 T72 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 38378 T72 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 38390 T78 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> 38390 T91 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> 38391 T111 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> 38391 T128 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> 38409 T71 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> 38418 T86 C16 P47721 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 38423 T86 C16 P47721 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=61
[junit4:junit4] 2> 38427 T114 C15 P46709 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 38427 T114 C15 P46709 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 38428 T114 C15 P46709 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 38437 T87 C16 P47721 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&generation=2&command=filelist&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 38439 T114 C15 P46709 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 38441 T114 C15 P46709 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index.20130618040427150
[junit4:junit4] 2> 38442 T114 C15 P46709 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index.20130618040427150 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5e5f1868; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 38461 T85 C16 P47721 oasc.SolrCore.execute [collection1] webapp= path=/replication params={checksum=true&qt=/replication&generation=2&command=filecontent&file=segments_2&wt=filestream} status=0 QTime=2
[junit4:junit4] 2> ASYNC NEW_CORE C17 name=collection1 org.apache.solr.core.SolrCore@29beb3a url=http://127.0.0.1:46709/collection1 node=127.0.0.1:46709_ C17_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:46709, state=recovering, node_name=127.0.0.1:46709_, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4] 2> 38578 T114 C17 P46709 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 38633 T114 C17 P46709 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 38642 T114 C17 P46709 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 38657 T114 C17 P46709 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b9dfbefb; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b9dfbefb; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 38666 T114 C17 P46709 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 38671 T114 C17 P46709 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 38673 T114 C17 P46709 oass.SolrIndexSearcher.<init> Opening Searcher@867a3a21 main
[junit4:junit4] 2> 38685 T113 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@867a3a21 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 38688 T114 C17 P46709 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index.20130618040427150 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index.20130618040427150;done=true>>]
[junit4:junit4] 2> 38692 T114 C17 P46709 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index.20130618040427150
[junit4:junit4] 2> 38694 T114 C17 P46709 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index.20130618040427150
[junit4:junit4] 2> 38713 T114 C17 P46709 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 38715 T114 C17 P46709 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 38721 T114 C17 P46709 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 38725 T114 C17 P46709 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 38738 T114 C17 P46709 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 39295 T129 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371503063703/collection1
[junit4:junit4] 2> 39296 T129 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 39297 T129 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 39298 T129 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 39302 T129 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371503063703/collection1/'
[junit4:junit4] 2> 39303 T129 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1371503063703/collection1/lib/README' to classloader
[junit4:junit4] 2> 39304 T129 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1371503063703/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 39422 T129 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 39516 T129 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 39539 T129 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 39610 T129 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 39918 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 39921 T72 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46709",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:46709__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:46709_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 39951 T71 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> 39951 T128 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> 39952 T78 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> 39952 T111 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> 39952 T91 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> 41522 T129 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 41543 T129 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 41549 T129 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 41716 T129 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 41748 T129 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 41793 T129 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 41814 T129 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 41818 T129 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 41819 T129 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 41832 T129 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 41834 T129 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 41837 T129 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 41841 T129 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty3-1371503063703/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/
[junit4:junit4] 2> 41845 T129 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a162f151
[junit4:junit4] 2> 41857 T129 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 41866 T129 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3
[junit4:junit4] 2> 41867 T129 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index/
[junit4:junit4] 2> 41870 T129 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 41876 T129 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index
[junit4:junit4] 2> 41896 T129 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@686b040c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 41900 T129 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 41931 T129 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 41934 T129 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 41937 T129 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 41950 T129 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 41963 T129 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 41967 T129 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 41984 T129 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 41993 T129 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 41998 T129 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 42007 T129 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 42035 T129 oass.SolrIndexSearcher.<init> Opening Searcher@29ed05cf main
[junit4:junit4] 2> 42036 T129 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 42037 T129 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 42080 T132 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@29ed05cf main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 42088 T129 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 42088 T129 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:38598 collection:collection1 shard:shard1
[junit4:junit4] 2> 42097 T129 oasc.ZkController.register We are http://127.0.0.1:38598/collection1/ and leader is http://127.0.0.1:47721/collection1/
[junit4:junit4] 2> 42098 T129 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:38598
[junit4:junit4] 2> 42098 T129 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 42099 T129 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> 42102 T129 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 42106 T45 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 42107 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 42108 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C18 name=collection1 org.apache.solr.core.SolrCore@6ad4961e url=http://127.0.0.1:38598/collection1 node=127.0.0.1:38598_ C18_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:38598, state=down, node_name=127.0.0.1:38598_, collection=collection1, core=collection1}
[junit4:junit4] 2> 42123 T133 C18 P38598 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 42124 T133 C18 P38598 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 42124 T133 C18 P38598 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 42125 T133 C18 P38598 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 42143 T133 C18 P38598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 42227 T84 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:38598__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 42701 T45 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 42704 T45 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:56240
[junit4:junit4] 2> 42705 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 42706 T45 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 42707 T45 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371503070868
[junit4:junit4] 2> 42708 T45 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371503070868/solr.xml
[junit4:junit4] 2> 42708 T45 oasc.CoreContainer.<init> New CoreContainer 1887522344
[junit4:junit4] 2> 42709 T45 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371503070868/'
[junit4:junit4] 2> 42710 T45 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371503070868/'
[junit4:junit4] 2> 42947 T45 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 42954 T45 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 42962 T45 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 42965 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 42972 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 42979 T72 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38598",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:38598__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:38598_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 43021 T45 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 43036 T128 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> 43034 T78 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> 43035 T111 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> 43035 T91 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> 43038 T71 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> 43049 T45 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 43090 T45 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 43092 T45 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 43094 T45 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 43104 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 43153 T45 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 43159 T45 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:51362/solr
[junit4:junit4] 2> 43168 T45 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 43185 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 43212 T145 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6259a686 name:ZooKeeperConnection Watcher:127.0.0.1:51362 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 43212 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 43225 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 43228 T84 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:38598__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 43229 T84 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=127.0.0.1:38598__collection1&wt=javabin&nodeName=127.0.0.1:38598_&core=collection1} status=0 QTime=1003
[junit4:junit4] 2> 43271 T45 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 43287 T147 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7587e424 name:ZooKeeperConnection Watcher:127.0.0.1:51362/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 43288 T45 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 43307 T45 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 44324 T45 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:56240_
[junit4:junit4] 2> 44327 T45 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:56240_
[junit4:junit4] 2> 44340 T111 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> 44340 T71 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> 44341 T91 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 44351 T91 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> 44344 T147 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 44340 T128 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> 44344 T78 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 44353 T78 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> 44353 T71 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 44348 T111 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 44358 T128 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 44401 T148 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 44403 T148 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 44582 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 44586 T72 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56240",
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:56240_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 44587 T72 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 44587 T72 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 44607 T91 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> 44608 T78 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> 44608 T147 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> 44608 T71 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> 44608 T111 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> 44608 T128 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> ASYNC NEW_CORE C19 name=collection1 org.apache.solr.core.SolrCore@6ad4961e url=http://127.0.0.1:38598/collection1 node=127.0.0.1:38598_ C19_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:38598, state=recovering, node_name=127.0.0.1:38598_, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4] 2> 45231 T133 C19 P38598 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:47721/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 45232 T133 C19 P38598 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38598 START replicas=[http://127.0.0.1:47721/collection1/] nUpdates=100
[junit4:junit4] 2> 45232 T133 C19 P38598 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 45233 T133 C19 P38598 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 45233 T133 C19 P38598 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 45234 T133 C19 P38598 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 45234 T133 C19 P38598 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 45235 T133 C19 P38598 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:47721/collection1/. core=collection1
[junit4:junit4] 2> 45235 T133 C19 P38598 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C20 name=collection1 org.apache.solr.core.SolrCore@6ca79287 url=http://127.0.0.1:47721/collection1 node=127.0.0.1:47721_ C20_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:47721, state=active, node_name=127.0.0.1:47721_, collection=collection1, shard=shard1, core=collection1, leader=true}
[junit4:junit4] 2> 45256 T85 C20 P47721 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 45313 T84 C20 P47721 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 45322 T84 C20 P47721 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 45324 T84 C20 P47721 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 45325 T84 C20 P47721 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 45326 T84 C20 P47721 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 14
[junit4:junit4] 2> 45341 T133 C19 P38598 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 45343 T133 C19 P38598 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 45351 T85 C20 P47721 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 45353 T133 C19 P38598 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 45355 T133 C19 P38598 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 45355 T133 C19 P38598 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 45362 T87 C20 P47721 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&generation=3&command=filelist&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 45365 T133 C19 P38598 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 45367 T133 C19 P38598 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index.20130618040434076
[junit4:junit4] 2> 45368 T133 C19 P38598 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index.20130618040434076 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3c971a37; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 45383 T84 C20 P47721 oasc.SolrCore.execute [collection1] webapp= path=/replication params={checksum=true&qt=/replication&generation=3&command=filecontent&file=segments_3&wt=filestream} status=0 QTime=1
[junit4:junit4] 2> 45387 T133 C19 P38598 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 45430 T133 C19 P38598 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 45437 T133 C19 P38598 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 45446 T148 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371503070868/collection1
[junit4:junit4] 2> 45447 T148 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 45448 T148 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 45449 T148 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 45451 T148 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371503070868/collection1/'
[junit4:junit4] 2> 45452 T148 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1371503070868/collection1/lib/README' to classloader
[junit4:junit4] 2> 45453 T148 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1371503070868/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 45453 T133 C19 P38598 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@686b040c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@686b040c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 45463 T133 C19 P38598 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 45464 T133 C19 P38598 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 45465 T133 C19 P38598 oass.SolrIndexSearcher.<init> Opening Searcher@3f392540 main
[junit4:junit4] 2> 45469 T132 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3f392540 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 45475 T133 C19 P38598 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index.20130618040434076 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index.20130618040434076;done=true>>]
[junit4:junit4] 2> 45479 T133 C19 P38598 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index.20130618040434076
[junit4:junit4] 2> 45481 T133 C19 P38598 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index.20130618040434076
[junit4:junit4] 2> 45482 T133 C19 P38598 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 45482 T133 C19 P38598 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 45483 T133 C19 P38598 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 45483 T133 C19 P38598 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 45489 T133 C19 P38598 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 45639 T148 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 45901 T148 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 45924 T148 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 45968 T148 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 46121 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 46124 T72 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:38598",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:38598__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:38598_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 46153 T91 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> 46153 T111 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> 46154 T147 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> 46154 T78 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> 46154 T128 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> 46157 T71 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> 47642 T148 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 47655 T148 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 47661 T148 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 47763 T148 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 47776 T148 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 47806 T148 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 47819 T148 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 47872 T148 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 47873 T148 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 47879 T148 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 47882 T148 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 47887 T148 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 47888 T148 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.SyncSliceTest-jetty4-1371503070868/collection1/, dataDir=./org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/
[junit4:junit4] 2> 47889 T148 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a162f151
[junit4:junit4] 2> 47890 T148 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 47891 T148 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4
[junit4:junit4] 2> 47891 T148 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index/
[junit4:junit4] 2> 47892 T148 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 47893 T148 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index
[junit4:junit4] 2> 47938 T148 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b1a32; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 47939 T148 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 47960 T148 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 47962 T148 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 47966 T148 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 47979 T148 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 47986 T148 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 47987 T148 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 48007 T148 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 48012 T148 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 48013 T148 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 48019 T148 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 48029 T148 oass.SolrIndexSearcher.<init> Opening Searcher@bd4adfa7 main
[junit4:junit4] 2> 48031 T148 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 48043 T148 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 48076 T151 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@bd4adfa7 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 48113 T148 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 48114 T148 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:56240 collection:collection1 shard:shard1
[junit4:junit4] 2> 48127 T148 oasc.ZkController.register We are http://127.0.0.1:56240/collection1/ and leader is http://127.0.0.1:47721/collection1/
[junit4:junit4] 2> 48128 T148 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:56240
[junit4:junit4] 2> 48129 T148 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 48129 T148 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> 48133 T148 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 48140 T45 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 48141 T45 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 48142 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C21 name=collection1 org.apache.solr.core.SolrCore@6a883c6f url=http://127.0.0.1:56240/collection1 node=127.0.0.1:56240_ C21_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:56240, state=down, node_name=127.0.0.1:56240_, collection=collection1, core=collection1}
[junit4:junit4] 2> 48146 T152 C21 P56240 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 48150 T152 C21 P56240 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 48154 T152 C21 P56240 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 48158 T152 C21 P56240 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 48163 T152 C21 P56240 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 48155 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 48184 T45 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 48185 T45 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 48191 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 48224 T85 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:56240__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 49177 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 49180 T72 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56240",
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:56240__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:56240_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 49190 T78 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> 49190 T71 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> 49191 T147 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> 49191 T111 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> 49191 T91 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> 49191 T128 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> 49197 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 49225 T85 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:56240__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 49226 T85 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={state=recovering&onlyIfLeader=true&checkLive=true&action=PREPRECOVERY&version=2&coreNodeName=127.0.0.1:56240__collection1&wt=javabin&nodeName=127.0.0.1:56240_&core=collection1} status=0 QTime=1003
[junit4:junit4] 2> 50200 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 51204 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C21_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:56240, state=recovering, node_name=127.0.0.1:56240_, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4] 2> 51231 T152 C21 P56240 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:47721/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 51232 T152 C21 P56240 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56240 START replicas=[http://127.0.0.1:47721/collection1/] nUpdates=100
[junit4:junit4] 2> 51232 T152 C21 P56240 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 51233 T152 C21 P56240 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 51233 T152 C21 P56240 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 51234 T152 C21 P56240 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 51234 T152 C21 P56240 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 51235 T152 C21 P56240 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:47721/collection1/. core=collection1
[junit4:junit4] 2> 51235 T152 C21 P56240 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C22 name=collection1 org.apache.solr.core.SolrCore@6ca79287 url=http://127.0.0.1:47721/collection1 node=127.0.0.1:47721_ C22_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:47721, state=active, node_name=127.0.0.1:47721_, collection=collection1, shard=shard1, core=collection1, leader=true}
[junit4:junit4] 2> 51237 T86 C22 P47721 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 51259 T84 C22 P47721 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 51271 T84 C22 P47721 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 51272 T84 C22 P47721 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 51273 T84 C22 P47721 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 51274 T84 C22 P47721 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin&openSearcher=false} {commit=} 0 15
[junit4:junit4] 2> 51277 T152 C21 P56240 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 51277 T152 C21 P56240 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 51283 T85 C22 P47721 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&command=indexversion&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 51286 T152 C21 P56240 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 51286 T152 C21 P56240 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 51287 T152 C21 P56240 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 51294 T87 C22 P47721 oasc.SolrCore.execute [collection1] webapp= path=/replication params={qt=/replication&version=2&generation=4&command=filelist&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 51296 T152 C21 P56240 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 51297 T152 C21 P56240 oasc.CachingDirectoryFactory.get return new directory for /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index.20130618040440007
[junit4:junit4] 2> 51298 T152 C21 P56240 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index.20130618040440007 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6f74e01b; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 51308 T84 C22 P47721 oasc.SolrCore.execute [collection1] webapp= path=/replication params={checksum=true&qt=/replication&generation=4&command=filecontent&file=segments_4&wt=filestream} status=0 QTime=1
[junit4:junit4] 2> 51312 T152 C21 P56240 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 51334 T152 C21 P56240 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 51335 T152 C21 P56240 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 51341 T152 C21 P56240 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b1a32; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b1a32; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 51343 T152 C21 P56240 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 51343 T152 C21 P56240 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 51344 T152 C21 P56240 oass.SolrIndexSearcher.<init> Opening Searcher@65bb0520 main
[junit4:junit4] 2> 51351 T151 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@65bb0520 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 51353 T152 C21 P56240 oasc.CachingDirectoryFactory.closeCacheValue looking to close /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index.20130618040440007 [CachedDir<<refCount=0;path=/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index.20130618040440007;done=true>>]
[junit4:junit4] 2> 51355 T152 C21 P56240 oasc.CachingDirectoryFactory.close Closing directory: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index.20130618040440007
[junit4:junit4] 2> 51358 T152 C21 P56240 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: /mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index.20130618040440007
[junit4:junit4] 2> 51359 T152 C21 P56240 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 51360 T152 C21 P56240 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 51361 T152 C21 P56240 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 51361 T152 C21 P56240 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 51367 T152 C21 P56240 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 52207 T72 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52211 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 52212 T72 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:56240",
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:56240__collection1",
[junit4:junit4] 2> "node_name":"127.0.0.1:56240_",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "core":"collection1"}
[junit4:junit4] 2> 52220 T111 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> 52220 T147 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> 52220 T78 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> 52220 T71 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> 52220 T91 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> 52220 T128 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> 53217 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53219 T45 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C23 name=collection1 org.apache.solr.core.SolrCore@63fa8e65 url=http://127.0.0.1:33883/collection1 node=127.0.0.1:33883_ C23_STATE=coll:control_collection core:collection1 props:{base_url=http://127.0.0.1:33883, state=active, node_name=127.0.0.1:33883_, collection=control_collection, shard=shard1, core=collection1, leader=true}
[junit4:junit4] 2> 53229 T67 C23 P33883 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 53233 T67 C23 P33883 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@f557b435; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 53234 T67 C23 P33883 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 53263 T67 C23 P33883 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@f557b435; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@f557b435; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 53265 T67 C23 P33883 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 53269 T67 C23 P33883 oass.SolrIndexSearcher.<init> Opening Searcher@7ac5ec4e main
[junit4:junit4] 2> 53270 T67 C23 P33883 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 53272 T75 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7ac5ec4e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 53274 T67 C23 P33883 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&commit=true&version=2&waitSearcher=true&wt=javabin} {commit=} 0 45
[junit4:junit4] 2> 53286 T87 C22 P47721 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:47721/collection1/, StdNode: http://127.0.0.1:46709/collection1/, StdNode: http://127.0.0.1:38598/collection1/, StdNode: http://127.0.0.1:56240/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 53312 T86 C22 P47721 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C21_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:56240, state=active, node_name=127.0.0.1:56240_, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4] 2> 53320 T143 C21 P56240 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C24 name=collection1 org.apache.solr.core.SolrCore@29beb3a url=http://127.0.0.1:46709/collection1 node=127.0.0.1:46709_ C24_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:46709, state=active, node_name=127.0.0.1:46709_, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4] 2> 53325 T107 C24 P46709 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 53331 T86 C22 P47721 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 53332 T86 C22 P47721 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> ASYNC NEW_CORE C25 name=collection1 org.apache.solr.core.SolrCore@6ad4961e url=http://127.0.0.1:38598/collection1 node=127.0.0.1:38598_ C25_STATE=coll:collection1 core:collection1 props:{base_url=http://127.0.0.1:38598, state=active, node_name=127.0.0.1:38598_, collection=collection1, shard=shard1, core=collection1}
[junit4:junit4] 2> 53333 T117 C25 P38598 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 53333 T86 C22 P47721 oass.SolrIndexSearcher.<init> Opening Searcher@c6ab42e9 main
[junit4:junit4] 2> 53335 T86 C22 P47721 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 53338 T93 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c6ab42e9 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 53340 T86 C22 P47721 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&expungeDeletes=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin} {commit=} 0 28
[junit4:junit4] 2> 53341 T143 C21 P56240 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b1a32; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b1a32; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 53344 T143 C21 P56240 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 53345 T143 C21 P56240 oass.SolrIndexSearcher.<init> Opening Searcher@1f97635e main
[junit4:junit4] 2> 53346 T143 C21 P56240 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 53349 T151 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f97635e main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 53350 T143 C21 P56240 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&expungeDeletes=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin} {commit=} 0 30
[junit4:junit4] 2> 53351 T107 C24 P46709 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b9dfbefb; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b9dfbefb; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 53352 T107 C24 P46709 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 53354 T107 C24 P46709 oass.SolrIndexSearcher.<init> Opening Searcher@19c06666 main
[junit4:junit4] 2> 53355 T107 C24 P46709 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 53357 T113 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@19c06666 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 53358 T107 C24 P46709 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&expungeDeletes=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin} {commit=} 0 33
[junit4:junit4] 2> 53371 T117 C25 P38598 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@686b040c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@686b040c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 53372 T117 C25 P38598 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 53373 T117 C25 P38598 oass.SolrIndexSearcher.<init> Opening Searcher@9414b9a main
[junit4:junit4] 2> 53373 T117 C25 P38598 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 53376 T132 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9414b9a main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 53377 T117 C25 P38598 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&expungeDeletes=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin} {commit=} 0 45
[junit4:junit4] 2> 53379 T87 C22 P47721 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&commit=true&version=2&waitSearcher=true&wt=javabin} {commit=} 0 93
[junit4:junit4] 2> 53383 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 53394 T86 C22 P47721 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&version=2&rows=0&wt=javabin} hits=0 status=0 QTime=1
[junit4:junit4] 2> 53409 T100 C24 P46709 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&version=2&rows=0&wt=javabin} hits=0 status=0 QTime=1
[junit4:junit4] 2> 53415 T120 C25 P38598 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&version=2&rows=0&wt=javabin} hits=0 status=0 QTime=1
[junit4:junit4] 2> 53420 T142 C21 P56240 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&version=2&rows=0&wt=javabin} hits=0 status=0 QTime=1
[junit4:junit4] 2> 55442 T66 C23 P33883 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {deleteByQuery=*:* (-1438125217966718976)} 0 7
[junit4:junit4] 2> 55481 T142 C21 P56240 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438125218000273408&version=2&wt=javabin&update.from=http://127.0.0.1:47721/collection1/} {deleteByQuery=*:* (-1438125218000273408)} 0 2
[junit4:junit4] 2> 55484 T97 C24 P46709 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438125218000273408&version=2&wt=javabin&update.from=http://127.0.0.1:47721/collection1/} {deleteByQuery=*:* (-1438125218000273408)} 0 3
[junit4:junit4] 2> 55486 T118 C25 P38598 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438125218000273408&version=2&wt=javabin&update.from=http://127.0.0.1:47721/collection1/} {deleteByQuery=*:* (-1438125218000273408)} 0 2
[junit4:junit4] 2> 55489 T84 C22 P47721 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&version=2&wt=javabin} {deleteByQuery=*:* (-1438125218000273408)} 0 17
[junit4:junit4] 2> 55491 T100 C24 P46709 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {deleteByQuery=*:*} 0 45
[junit4:junit4] 2> 55500 T67 C23 P33883 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[0 (1438125218025439232)]} 0 4
[junit4:junit4] 2> 55529 T143 C21 P56240 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:47721/collection1/&version=2&wt=javabin} {add=[0 (1438125218041167872)]} 0 5
[junit4:junit4] 2> 55530 T123 C25 P38598 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:47721/collection1/&version=2&wt=javabin} {add=[0 (1438125218041167872)]} 0 4
[junit4:junit4] 2> 55543 T102 C24 P46709 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:47721/collection1/&version=2&wt=javabin} {add=[0 (1438125218041167872)]} 0 6
[junit4:junit4] 2> 55545 T86 C22 P47721 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&distrib.from=http://127.0.0.1:46709/collection1/&version=2&wt=javabin} {add=[0 (1438125218041167872)]} 0 33
[junit4:junit4] 2> 55547 T105 C24 P46709 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[0]} 0 42
[junit4:junit4] 2> 55555 T64 C23 P33883 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[1 (1438125218084159488)]} 0 3
[junit4:junit4] 2> 55577 T120 C25 P38598 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:47721/collection1/&version=2&wt=javabin} {add=[1 (1438125218096742400)]} 0 4
[junit4:junit4] 2> 55577 T141 C21 P56240 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:47721/collection1/&version=2&wt=javabin} {add=[1 (1438125218096742400)]} 0 4
[junit4:junit4] 2> 55578 T96 C24 P46709 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:47721/collection1/&version=2&wt=javabin} {add=[1 (1438125218096742400)]} 0 4
[junit4:junit4] 2> 55590 T87 C22 P47721 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&distrib.from=http://127.0.0.1:38598/collection1/&version=2&wt=javabin} {add=[1 (1438125218096742400)]} 0 26
[junit4:junit4] 2> 55603 T117 C25 P38598 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[1]} 0 43
[junit4:junit4] 2> 55614 T65 C23 P33883 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[2 (1438125218144976896)]} 0 5
[junit4:junit4] 2> 55623 T84 C22 P47721 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:46709/collection1/]
[junit4:junit4] 2> 55624 T84 C22 P47721 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:46709/collection1/ against:[http://127.0.0.1:46709/collection1/] result:true
[junit4:junit4] 2> 55624 T84 C22 P47721 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:38598/collection1/ against:[http://127.0.0.1:46709/collection1/] result:false
[junit4:junit4] 2> 55625 T84 C22 P47721 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:56240/collection1/ against:[http://127.0.0.1:46709/collection1/] result:false
[junit4:junit4] 2> 55637 T118 C25 P38598 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:47721/collection1/&test.distrib.skip.servers=http://127.0.0.1:46709/collection1/&version=2&wt=javabin} {add=[2 (1438125218160705536)]} 0 3
[junit4:junit4] 2> 55637 T140 C21 P56240 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:47721/collection1/&test.distrib.skip.servers=http://127.0.0.1:46709/collection1/&version=2&wt=javabin} {add=[2 (1438125218160705536)]} 0 3
[junit4:junit4] 2> 55641 T84 C22 P47721 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:46709/collection1/&version=2&wt=javabin} {add=[2 (1438125218160705536)]} 0 19
[junit4:junit4] 2> 55649 T66 C23 P33883 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={version=2&wt=javabin} {add=[3 (1438125218182725632)]} 0 3
[junit4:junit4] 2> 55663 T86 C22 P47721 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:46709/collection1/]
[junit4:junit4] 2> 55664 T86 C22 P47721 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:46709/collection1/ against:[http://127.0.0.1:46709/collection1/] result:true
[junit4:junit4] 2> 55664 T86 C22 P47721 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:38598/collection1/ against:[http://127.0.0.1:46709/collection1/] result:false
[junit4:junit4] 2> 55665 T86 C22 P47721 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:56240/collection1/ against:[http://127.0.0.1:46709/collection1/] result:false
[junit4:junit4] 2> 55678 T142 C21 P56240 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:47721/collection1/&test.distrib.skip.servers=http://127.0.0.1:46709/collection1/&version=2&wt=javabin} {add=[3 (1438125218202648576)]} 0 5
[junit4:junit4] 2> 55684 T120 C25 P38598 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&distrib.from=http://127.0.0.1:47721/collection1/&test.distrib.skip.servers=http://127.0.0.1:46709/collection1/&version=2&wt=javabin} {add=[3 (1438125218202648576)]} 0 4
[junit4:junit4] 2> 55686 T86 C22 P47721 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&distrib.from=http://127.0.0.1:38598/collection1/&test.distrib.skip.servers=http://127.0.0.1:46709/collection1/&version=2&wt=javabin} {add=[3 (1438125218202648576)]} 0 24
[junit4:junit4] 2> 55688 T123 C25 P38598 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={test.distrib.skip.servers=http://127.0.0.1:46709/collection1/&test.distrib.skip.servers=http://127.0.0.1:38598/collection1/&version=2&wt=javabin} {add=[3]} 0 31
[junit4:junit4] 2> 55692 T67 C23 P33883 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 55731 T67 C23 P33883 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@f557b435; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/control/data/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@f557b435; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 55732 T67 C23 P33883 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 55765 T67 C23 P33883 oass.SolrIndexSearcher.<init> Opening Searcher@1d49b504 main
[junit4:junit4] 2> 55779 T75 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d49b504 main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 55792 T67 C23 P33883 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 55793 T67 C23 P33883 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&commit=true&version=2&waitSearcher=true&wt=javabin} {commit=} 0 101
[junit4:junit4] 2> 55807 T141 C21 P56240 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:47721/collection1/, StdNode: http://127.0.0.1:46709/collection1/, StdNode: http://127.0.0.1:38598/collection1/, StdNode: http://127.0.0.1:56240/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 55820 T120 C25 P38598 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 55824 T99 C24 P46709 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 55827 T87 C22 P47721 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 55829 T143 C21 P56240 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 55861 T99 C24 P46709 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b9dfbefb; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty2/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b9dfbefb; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 55862 T120 C25 P38598 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@686b040c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty3/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@686b040c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 55862 T99 C24 P46709 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 55863 T120 C25 P38598 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 55866 T99 C24 P46709 oass.SolrIndexSearcher.<init> Opening Searcher@f3883f2a main
[junit4:junit4] 2> 55866 T120 C25 P38598 oass.SolrIndexSearcher.<init> Opening Searcher@696c44d8 main
[junit4:junit4] 2> 55867 T99 C24 P46709 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 55869 T113 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@f3883f2a main{StandardDirectoryReader(segments_4:3:nrt _0(4.4):c2)}
[junit4:junit4] 2> 55868 T120 C25 P38598 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 55869 T132 oasc.JmxMonitoredMap.put WARN Failed to register info bean: fieldValueCache javax.management.InstanceAlreadyExistsException: solr/collection1:type=fieldValueCache,id=org.apache.solr.search.FastLRUCache
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.Repository.addMBean(Repository.java:449)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerWithRepository(DefaultMBeanServerInterceptor.java:1910)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerDynamicMBean(DefaultMBeanServerInterceptor.java:978)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerObject(DefaultMBeanServerInterceptor.java:912)
[junit4:junit4] 2> at com.sun.jmx.interceptor.DefaultMBeanServerInterceptor.registerMBean(DefaultMBeanServerInterceptor.java:336)
[junit4:junit4] 2> at com.sun.jmx.mbeanserver.JmxMBeanServer.registerMBean(JmxMBeanServer.java:524)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:140)
[junit4:junit4] 2> at org.apache.solr.core.JmxMonitoredMap.put(JmxMonitoredMap.java:51)
[junit4:junit4] 2> at org.apache.solr.search.SolrIndexSearcher.register(SolrIndexSearcher.java:302)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.registerSearcher(SolrCore.java:1846)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore.access$000(SolrCore.java:135)
[junit4:junit4] 2> at org.apache.solr.core.SolrCore$7.call(SolrCore.java:1723)
[junit4:junit4] 2> at java.util.concurrent.FutureTask$Sync.innerRun(FutureTask.java:345)
[junit4:junit4] 2> at java.util.concurrent.FutureTask.run(FutureTask.java:177)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1121)
[junit4:junit4] 2> at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:614)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:780)
[junit4:junit4] 2>
[junit4:junit4] 2> 55870 T99 C24 P46709 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&expungeDeletes=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin} {commit=} 0 47
[junit4:junit4] 2> 55871 T87 C22 P47721 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty1/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@507c6ed2; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 55872 T132 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@696c44d8 main{StandardDirectoryReader(segments_5:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 55873 T87 C22 P47721 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 55875 T120 C25 P38598 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&expungeDeletes=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin} {commit=} 0 55
[junit4:junit4] 2> 55877 T87 C22 P47721 oass.SolrIndexSearcher.<init> Opening Searcher@7373f5e2 main
[junit4:junit4] 2> 55878 T87 C22 P47721 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 55880 T93 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7373f5e2 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 55881 T87 C22 P47721 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&expungeDeletes=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin} {commit=} 0 54
[junit4:junit4] 2> 55921 T143 C21 P56240 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b1a32; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.NIOFSDirectory@/mnt/ssd/jenkins/workspace/Lucene-Solr-4.x-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-1371503042293/jetty4/index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4b1a32; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 55922 T143 C21 P56240 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 55925 T143 C21 P56240 oass.SolrIndexSearcher.<init> Opening Searcher@806007a7 main
[junit4:junit4] 2> 55926 T143 C21 P56240 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 55928 T151 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@806007a7 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 55936 T143 C21 P56240 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&expungeDeletes=false&commit_end_point=true&commit=true&version=2&waitSearcher=true&wt=javabin} {commit=} 0 107
[junit4:junit4] 2> 55938 T141 C21 P56240 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={softCommit=false&commit=true&version=2&waitSearcher=true&wt=javabin} {commit=} 0 131
[junit4:junit4] 2> 55939 T45 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 55941 T45 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 55943 T45 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 55947 T86 C22 P47721 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&version=2&rows=0&wt=javabin} hits=4 status=0 QTime=1
[junit4:junit4] 2> 55952 T97 C24 P46709 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&version=2&rows=0&wt=javabin} hits=2 status=0 QTime=1
[junit4:junit4] 2> 55956 T123 C25 P38598 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&version=2&rows=0&wt=javabin} hits=4 status=0 QTime=0
[junit4:junit4] 2> 55961 T142 C21 P56240 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&version=2&rows=0&wt=javabin} hits=4 status=0 QTime=0
[junit4:junit4] 2> 55964 T45 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 55983 T120 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : action=SYNCSHARD&version=2&wt=javabin&shard=shard1&collection=collection1
[junit4:junit4] 2> 55984 T120 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 55994 T87 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 55995 T87 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:47721/collection1/
[junit4:junit4] 2> 55996 T87 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:47721 START replicas=[http://127.0.0.1:46709/collection1/, http://127.0.0.1:38598/collection1/, http://127.0.0.1:56240/collection1/] nUpdates=100
[junit4:junit4] 2> 56001 T123 C25 P38598 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 56015 T102 C24 P46709 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 56017 T140 C21 P56240 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 56017 T87 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:47721 Received 5 versions from 127.0.0.1:38598/collection1/
[junit4:junit4] 2> 56019 T87 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:47721 Our versions are newer. ourLowThreshold=1438125218000273408 otherHigh=1438125218160705536
[junit4:junit4] 2> 56019 T87 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:47721 Received 3 versions from 127.0.0.1:46709/collection1/
[junit4:junit4] 2> 56020 T87 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:47721 Our versions are newer. ourLowThreshold=1438125218000273408 otherHigh=1438125218096742400
[junit4:junit4] 2> 56021 T87 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:47721 Received 5 versions from 127.0.0.1:56240/collection1/
[junit4:junit4] 2> 56022 T87 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:47721 Our versions are newer. ourLowThreshold=1438125218000273408 otherHigh=1438125218160705536
[junit4:junit4] 2> 56023 T87 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:47721 DONE. sync succeeded
[junit4:junit4] 2> 56024 T87 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 56024 T87 oasc.SyncStrategy.syncToMe http://127.0.0.1:47721/collection1/: try and ask http://127.0.0.1:46709/collection1/ to sync
[junit4:junit4] 2> 56026 T87 oasc.SyncStrategy.syncToMe http://127.0.0.1:47721/collection1/: try and ask http://127.0.0.1:38598/collection1/ to sync
[junit4:junit4] 2> 56027 T87 oasc.SyncStrategy.syncToMe http://127.0.0.1:47721/collection1/: try and ask http://127.0.0.1:56240/collection1/ to sync
[junit4:junit4] 2> 56045 T107 C24 P46709 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:46709 START replicas=[http://127.0.0.1:47721/collection1/] nUpdates=100
[junit4:junit4] 2> 56046 T143 C21 P56240 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56240 START replicas=[http://127.0.0.1:47721/collection1/] nUpdates=100
[junit4:junit4] 2> 56048 T118 C25 P38598 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38598 START replicas=[http://127.0.0.1:47721/collection1/] nUpdates=100
[junit4:junit4] 2> 56052 T86 C22 P47721 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 56054 T84 C22 P47721 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=0
[junit4:junit4] 2> 56056 T107 C24 P46709 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:46709 Received 5 versions from 127.0.0.1:47721/collection1/
[junit4:junit4] 2> 56056 T143 C21 P56240 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:56240 Received 5 versions from 127.0.0.1:47721/collection1/
[junit4:junit4] 2> 56057 T107 C24 P46709 oasu.PeerSync.requestUpdates PeerSync: core=collection1 url=http://127.0.0.1:46709 Requesting updates from 127.0.0.1:47721/collection1/n=2 versions=[1438125218202648576, 1438125218160705536]
[junit4:junit4] 2> 56057 T143 C21 P56240 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:56240 Our versions are newer. ourLowThreshold=1438125218000273408 otherHigh=1438125218160705536
[junit4:junit4] 2> 56059 T143 C21 P56240 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:56240 DONE. sync succeeded
[junit4:junit4] 2> 56059 T143 C21 P56240 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&sync=http://127.0.0.1:47721/collection1/&wt=javabin} status=0 QTime=13
[junit4:junit4] 2> 56061 T87 oasc.SyncStrategy.syncToMe http://127.0.0.1:47721/collection1/: sync completed with http://127.0.0.1:56240/collection1/
[junit4:junit4] 2> 56063 T86 C22 P47721 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 56067 T85 C22 P47721 oasc.SolrCore.execute [collection1] webapp= path=/get params={qt=/get&getUpdates=1438125218202648576,1438125218160705536&distrib=false&version=2&wt=javabin} status=0 QTime=1
[junit4:junit4] 2> 56068 T118 C25 P38598 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:38598 Received 5 versions from 127.0.0.1:47721/collection1/
[junit4:junit4] 2> 56069 T118 C25 P38598 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:38598 Our versions are newer. ourLowThreshold=1438125218000273408 otherHigh=1438125218160705536
[junit4:junit4] 2> 56070 T118 C25 P38598 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:38598 DONE. sync succeeded
[junit4:junit4] 2> 56071 T118 C25 P38598 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&qt=/get&distrib=false&version=2&sync=http://127.0.0.1:47721/collection1/&wt=javabin} status=0 QTime=23
[junit4:junit4] 2> 56072 T87 oasc.SyncStrategy.syncToMe http://127.0.0.1:47721/collection1/: sync completed with http://127.0.0.1:38598/collection1/
[junit4:junit4] 2> 56081 T107 C24 P46709 oasup.LogUpdateProcessor.finish [collection1] {add=[2 (1438125218160705536),
[...truncated too long message...]
junit4] 1> /solr/collections/collection1/shards (0)
[junit4:junit4] 1> /solr/collections/onenodecollection (2)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "router":"compositeId",
[junit4:junit4] 1> "configName":"conf1"}
[junit4:junit4] 1> /solr/collections/onenodecollection/leader_elect (1)
[junit4:junit4] 1> /solr/collections/onenodecollection/leader_elect/shard1 (1)
[junit4:junit4] 1> /solr/collections/onenodecollection/leader_elect/shard1/election (1)
[junit4:junit4] 1> /solr/collections/onenodecollection/leader_elect/shard1/election/89882835704545286-127.0.0.1:47532__onenodecollectioncore-n_0000000000 (0)
[junit4:junit4] 1> /solr/collections/onenodecollection/leaders (1)
[junit4:junit4] 1> /solr/collections/onenodecollection/leaders/shard1 (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "base_url":"http://127.0.0.1:47532",
[junit4:junit4] 1> "node_name":"127.0.0.1:47532_",
[junit4:junit4] 1> "core":"onenodecollectioncore"}
[junit4:junit4] 1> /solr/aliases.json (0)
[junit4:junit4] 1> /solr/live_nodes (5)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:40385_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:38100_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:47532_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:58213_ (0)
[junit4:junit4] 1> /solr/live_nodes/127.0.0.1:39245_ (0)
[junit4:junit4] 1> /solr/clusterstate.json (0)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1> {
[junit4:junit4] 1> "control_collection":{
[junit4:junit4] 1> "shards":{"shard1":{
[junit4:junit4] 1> "range":"80000000-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{"127.0.0.1:58213__collection1":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:58213",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:58213_",
[junit4:junit4] 1> "collection":"control_collection",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "leader":"true"}}}},
[junit4:junit4] 1> "router":"compositeId"},
[junit4:junit4] 1> "onenodecollection":{
[junit4:junit4] 1> "shards":{"shard1":{
[junit4:junit4] 1> "range":"80000000-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{"127.0.0.1:47532__onenodecollectioncore":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:47532",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:47532_",
[junit4:junit4] 1> "roles":"none",
[junit4:junit4] 1> "collection":"onenodecollection",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"onenodecollectioncore",
[junit4:junit4] 1> "leader":"true"}}}},
[junit4:junit4] 1> "router":"compositeId"},
[junit4:junit4] 1> "collection1":{
[junit4:junit4] 1> "shards":{
[junit4:junit4] 1> "shard1":{
[junit4:junit4] 1> "range":"80000000-ffffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{
[junit4:junit4] 1> "127.0.0.1:47532__collection1":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:47532",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:47532_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "leader":"true"},
[junit4:junit4] 1> "127.0.0.1:40385__collection1":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:40385",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:40385_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard1",
[junit4:junit4] 1> "core":"collection1"}}},
[junit4:junit4] 1> "shard2":{
[junit4:junit4] 1> "range":"0-7fffffff",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "replicas":{
[junit4:junit4] 1> "127.0.0.1:38100__collection1":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:38100",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:38100_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "core":"collection1",
[junit4:junit4] 1> "leader":"true"},
[junit4:junit4] 1> "127.0.0.1:39245__collection1":{
[junit4:junit4] 1> "base_url":"http://127.0.0.1:39245",
[junit4:junit4] 1> "state":"active",
[junit4:junit4] 1> "node_name":"127.0.0.1:39245_",
[junit4:junit4] 1> "collection":"collection1",
[junit4:junit4] 1> "shard":"shard2",
[junit4:junit4] 1> "core":"collection1"}}}},
[junit4:junit4] 1> "router":"compositeId"}}
[junit4:junit4] 1> /zookeeper (1)
[junit4:junit4] 1> DATA:
[junit4:junit4] 1>
[junit4:junit4] 1>
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=BasicDistributedZk2Test -Dtests.method=testDistribSearch -Dtests.seed=7F8D4AFFE52C4384 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=en_SG -Dtests.timezone=America/Panama -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR 29.2s J1 | BasicDistributedZk2Test.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:38100/onenodecollectioncore returned non ok status:404, message:Can not find: /onenodecollectioncore/update
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([7F8D4AFFE52C4384:FE6BC4E7927323B8]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.client.solrj.request.AbstractUpdateRequest.process(AbstractUpdateRequest.java:117)
[junit4:junit4] > at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:116)
[junit4:junit4] > at org.apache.solr.client.solrj.SolrServer.add(SolrServer.java:102)
[junit4:junit4] > at org.apache.solr.cloud.BasicDistributedZk2Test.testNodeWithoutCollectionForwarding(BasicDistributedZk2Test.java:198)
[junit4:junit4] > at org.apache.solr.cloud.BasicDistributedZk2Test.doTest(BasicDistributedZk2Test.java:90)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:780)
[junit4:junit4] 2> 231093 T706 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 29243 T705 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=en_SG, timezone=America/Panama
[junit4:junit4] 2> NOTE: Linux 3.2.0-48-generic x86/IBM Corporation 1.7.0 (32-bit)/cpus=8,threads=2,free=37741120,total=174718976
[junit4:junit4] 2> NOTE: All tests run in this JVM: [HighlighterTest, TestArbitraryIndexDir, TestAddFieldRealTimeGet, TestIndexingPerformance, TestCollationField, SimplePostToolTest, TestShardHandlerFactory, CoreContainerCoreInitFailuresTest, DefaultValueUpdateProcessorTest, OpenCloseCoreStressTest, TestManagedSchema, ChaosMonkeySafeLeaderTest, JSONWriterTest, SolrRequestParserTest, DOMUtilTest, FileUtilsTest, DisMaxRequestHandlerTest, TestAtomicUpdateErrorCases, BasicDistributedZk2Test]
[junit4:junit4] Completed on J1 in 29.76s, 1 test, 1 error <<< FAILURES!
[...truncated 774 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:385: 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, 1252 tests, 1 error, 1 failure, 14 ignored (8 assumptions)
Total time: 44 minutes 6 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/ibm-j9-jdk7 -Xjit:exclude={org/apache/lucene/util/fst/FST.pack(IIF)Lorg/apache/lucene/util/fst/FST;}
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure