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/19 17:00:54 UTC
[JENKINS] Lucene-Solr-trunk-Windows (64bit/jdk1.7.0_21) - Build #
2947 - Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Windows/2947/
Java: 64bit/jdk1.7.0_21 -XX:+UseCompressedOops -XX:+UseSerialGC
2 tests failed.
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:59045 returned non ok status:500, message:Server Error
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:59045 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([EB2C8B79ABA1A1E1:6ACA0561DCFEC1DD]: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.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:150)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.GeneratedMethodAccessor44.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
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:722)
FAILED: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:55853/_qvl/u/collection1lastClient and got 257 from http://127.0.0.1:55872/_qvl/u/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:55853/_qvl/u/collection1lastClient and got 257 from http://127.0.0.1:55872/_qvl/u/collection1
at __randomizedtesting.SeedInfo.seed([EB2C8B79ABA1A1E1:6ACA0561DCFEC1DD]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
at org.apache.solr.cloud.SyncSliceTest.doTest(SyncSliceTest.java:238)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
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:722)
Build Log:
[...truncated 9341 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 642913 T2166 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /_qvl/u
[junit4:junit4] 2> 642919 T2166 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\solrtest-SyncSliceTest-1371651843142
[junit4:junit4] 2> 642923 T2166 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 642925 T2167 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 643025 T2166 oasc.ZkTestServer.run start zk server on port:55834
[junit4:junit4] 2> 643027 T2166 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 643068 T2173 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@80bb86a name:ZooKeeperConnection Watcher:127.0.0.1:55834 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 643068 T2166 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 643069 T2166 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 643086 T2166 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 643091 T2175 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@72994181 name:ZooKeeperConnection Watcher:127.0.0.1:55834/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 643091 T2166 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 643091 T2166 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 643100 T2166 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 643106 T2166 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 643111 T2166 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 643117 T2166 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 643117 T2166 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 643125 T2166 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 643126 T2166 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 643134 T2166 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 643134 T2166 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 643140 T2166 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 643140 T2166 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 643147 T2166 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 643147 T2166 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 643152 T2166 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 643153 T2166 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 643162 T2166 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 643162 T2166 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 643168 T2166 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 643169 T2166 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 643175 T2166 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 643175 T2166 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 643185 T2168 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f5cd224500001, 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:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 643621 T2166 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 643629 T2166 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55841
[junit4:junit4] 2> 643630 T2166 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 643630 T2166 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 643631 T2166 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-controljetty-1371651843404
[junit4:junit4] 2> 643631 T2166 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-controljetty-1371651843404\solr.xml
[junit4:junit4] 2> 643632 T2166 oasc.CoreContainer.<init> New CoreContainer 2143129908
[junit4:junit4] 2> 643632 T2166 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-controljetty-1371651843404\'
[junit4:junit4] 2> 643632 T2166 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-controljetty-1371651843404\'
[junit4:junit4] 2> 643735 T2166 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 643736 T2166 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 643736 T2166 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 643737 T2166 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 643737 T2166 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 643737 T2166 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 643738 T2166 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 643738 T2166 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 643738 T2166 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 643739 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 643747 T2166 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 643748 T2166 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55834/solr
[junit4:junit4] 2> 643748 T2166 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 643750 T2166 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 643766 T2186 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2c45cd4b name:ZooKeeperConnection Watcher:127.0.0.1:55834 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 643767 T2166 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 643771 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 643779 T2166 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 643784 T2188 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@156a3a93 name:ZooKeeperConnection Watcher:127.0.0.1:55834/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 643784 T2166 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 643788 T2166 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 643796 T2166 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 643804 T2166 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 643809 T2166 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55841__qvl%2Fu
[junit4:junit4] 2> 643812 T2166 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55841__qvl%2Fu
[junit4:junit4] 2> 643820 T2166 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 643835 T2166 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 643841 T2166 oasc.Overseer.start Overseer (id=89892575192809475-127.0.0.1:55841__qvl%2Fu-n_0000000000) starting
[junit4:junit4] 2> 643851 T2166 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 643861 T2190 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 643863 T2166 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 643869 T2166 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 643875 T2166 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 643880 T2189 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 643901 T2191 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 643901 T2191 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 645253 T2189 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 645254 T2189 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55841__qvl%2Fu",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55841/_qvl/u"}
[junit4:junit4] 2> 645254 T2189 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 645254 T2189 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 645264 T2188 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> 645700 T2191 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-controljetty-1371651843404\collection1
[junit4:junit4] 2> 645700 T2191 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 645703 T2191 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 645704 T2191 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 645708 T2191 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-controljetty-1371651843404\collection1\'
[junit4:junit4] 2> 645713 T2191 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1371651843404/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 645713 T2191 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1371651843404/collection1/lib/README' to classloader
[junit4:junit4] 2> 645779 T2191 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 645829 T2191 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 645831 T2191 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 645835 T2191 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 646378 T2191 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 646387 T2191 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 646389 T2191 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 646407 T2191 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 646410 T2191 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 646415 T2191 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 646416 T2191 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 646416 T2191 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 646416 T2191 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 646418 T2191 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 646418 T2191 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 646418 T2191 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 646419 T2191 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-controljetty-1371651843404\collection1\, dataDir=.\org.apache.solr.cloud.SyncSliceTest-1371651843140/control/data\
[junit4:junit4] 2> 646419 T2191 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a80dee3
[junit4:junit4] 2> 646419 T2191 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 646421 T2191 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\control\data
[junit4:junit4] 2> 646422 T2191 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.SyncSliceTest-1371651843140/control/data\index/
[junit4:junit4] 2> 646422 T2191 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.SyncSliceTest-1371651843140\control\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 646422 T2191 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\control\data\index
[junit4:junit4] 2> 646432 T2191 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b52e997; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 646432 T2191 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 646436 T2191 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 646436 T2191 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 646436 T2191 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 646436 T2191 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 646437 T2191 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 646437 T2191 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 646437 T2191 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 646438 T2191 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 646438 T2191 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 646447 T2191 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 646455 T2191 oass.SolrIndexSearcher.<init> Opening Searcher@551e9d03 main
[junit4:junit4] 2> 646457 T2191 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 646457 T2191 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 646461 T2192 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@551e9d03 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 646462 T2191 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 646462 T2191 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55841/_qvl/u collection:control_collection shard:shard1
[junit4:junit4] 2> 646463 T2191 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 646477 T2191 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 646483 T2191 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 646483 T2191 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 646483 T2191 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:55841/_qvl/u/collection1/
[junit4:junit4] 2> 646483 T2191 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 646483 T2191 oasc.SyncStrategy.syncToMe http://127.0.0.1:55841/_qvl/u/collection1/ has no replicas
[junit4:junit4] 2> 646483 T2191 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:55841/_qvl/u/collection1/
[junit4:junit4] 2> 646483 T2191 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 646608 T2189 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 646622 T2188 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> 646640 T2191 oasc.ZkController.register We are http://127.0.0.1:55841/_qvl/u/collection1/ and leader is http://127.0.0.1:55841/_qvl/u/collection1/
[junit4:junit4] 2> 646640 T2191 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55841/_qvl/u
[junit4:junit4] 2> 646640 T2191 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 646640 T2191 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 646640 T2191 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 646647 T2191 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 646648 T2166 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 646648 T2166 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 646649 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 646656 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 646660 T2166 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 646665 T2195 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@429a523e name:ZooKeeperConnection Watcher:127.0.0.1:55834/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 646666 T2166 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 646669 T2166 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 646672 T2166 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 647046 T2166 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 647051 T2166 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55853
[junit4:junit4] 2> 647052 T2166 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 647053 T2166 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 647053 T2166 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty1-1371651846892
[junit4:junit4] 2> 647054 T2166 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty1-1371651846892\solr.xml
[junit4:junit4] 2> 647054 T2166 oasc.CoreContainer.<init> New CoreContainer 331851221
[junit4:junit4] 2> 647055 T2166 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty1-1371651846892\'
[junit4:junit4] 2> 647056 T2166 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty1-1371651846892\'
[junit4:junit4] 2> 647166 T2166 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 647166 T2166 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 647166 T2166 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 647166 T2166 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 647166 T2166 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 647168 T2166 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 647168 T2166 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 647168 T2166 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 647169 T2166 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 647170 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 647180 T2166 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 647182 T2166 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55834/solr
[junit4:junit4] 2> 647183 T2166 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 647185 T2166 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 647199 T2206 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@647c4c23 name:ZooKeeperConnection Watcher:127.0.0.1:55834 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 647200 T2166 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 647205 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 647213 T2166 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 647218 T2208 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@391a7fc5 name:ZooKeeperConnection Watcher:127.0.0.1:55834/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 647218 T2166 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 647227 T2166 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 647967 T2189 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 647968 T2189 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55841__qvl%2Fu",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55841/_qvl/u"}
[junit4:junit4] 2> 647979 T2195 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> 647980 T2188 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> 647980 T2208 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> 648122 T2166 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55853__qvl%2Fu
[junit4:junit4] 2> 648124 T2166 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55853__qvl%2Fu
[junit4:junit4] 2> 648130 T2195 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 648131 T2195 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> 648131 T2208 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 648131 T2208 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> 648131 T2188 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 648131 T2188 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> 648142 T2209 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 648142 T2209 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 649326 T2189 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 649327 T2189 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55853__qvl%2Fu",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55853/_qvl/u"}
[junit4:junit4] 2> 649327 T2189 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 649327 T2189 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 649338 T2208 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> 649338 T2188 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> 649338 T2195 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> 649926 T2209 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty1-1371651846892\collection1
[junit4:junit4] 2> 649926 T2209 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 649928 T2209 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 649928 T2209 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 649931 T2209 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty1-1371651846892\collection1\'
[junit4:junit4] 2> 649933 T2209 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1371651846892/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 649934 T2209 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1371651846892/collection1/lib/README' to classloader
[junit4:junit4] 2> 649992 T2209 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 650049 T2209 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 650053 T2209 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 650056 T2209 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 650649 T2209 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 650657 T2209 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 650662 T2209 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 650688 T2209 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 650696 T2209 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 650702 T2209 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 650704 T2209 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 650705 T2209 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 650705 T2209 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 650707 T2209 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 650707 T2209 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 650707 T2209 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 650708 T2209 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty1-1371651846892\collection1\, dataDir=.\org.apache.solr.cloud.SyncSliceTest-1371651843140/jetty1\
[junit4:junit4] 2> 650708 T2209 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a80dee3
[junit4:junit4] 2> 650708 T2209 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 650709 T2209 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1
[junit4:junit4] 2> 650710 T2209 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.SyncSliceTest-1371651843140/jetty1\index/
[junit4:junit4] 2> 650710 T2209 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 650710 T2209 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index
[junit4:junit4] 2> 650725 T2209 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 650725 T2209 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 650728 T2209 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 650729 T2209 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 650729 T2209 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 650730 T2209 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 650730 T2209 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 650730 T2209 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 650730 T2209 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 650731 T2209 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 650731 T2209 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 650743 T2209 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 650756 T2209 oass.SolrIndexSearcher.<init> Opening Searcher@13098d44 main
[junit4:junit4] 2> 650757 T2209 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 650757 T2209 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 650762 T2209 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 650762 T2209 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55853/_qvl/u collection:collection1 shard:shard1
[junit4:junit4] 2> 650763 T2210 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@13098d44 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 650769 T2209 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 650791 T2209 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 650799 T2209 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 650799 T2209 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 650800 T2209 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:55853/_qvl/u/collection1/
[junit4:junit4] 2> 650800 T2209 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 650800 T2209 oasc.SyncStrategy.syncToMe http://127.0.0.1:55853/_qvl/u/collection1/ has no replicas
[junit4:junit4] 2> 650801 T2209 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:55853/_qvl/u/collection1/
[junit4:junit4] 2> 650802 T2209 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 652023 T2189 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 652043 T2208 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> 652043 T2188 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> 652043 T2195 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> 652087 T2209 oasc.ZkController.register We are http://127.0.0.1:55853/_qvl/u/collection1/ and leader is http://127.0.0.1:55853/_qvl/u/collection1/
[junit4:junit4] 2> 652087 T2209 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55853/_qvl/u
[junit4:junit4] 2> 652087 T2209 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 652087 T2209 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 652087 T2209 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 652090 T2209 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 652091 T2166 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 652091 T2166 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 652092 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 652470 T2166 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 652476 T2166 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55862
[junit4:junit4] 2> 652477 T2166 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 652477 T2166 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 652478 T2166 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty2-1371651852318
[junit4:junit4] 2> 652478 T2166 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty2-1371651852318\solr.xml
[junit4:junit4] 2> 652478 T2166 oasc.CoreContainer.<init> New CoreContainer 1153256919
[junit4:junit4] 2> 652478 T2166 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty2-1371651852318\'
[junit4:junit4] 2> 652478 T2166 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty2-1371651852318\'
[junit4:junit4] 2> 652591 T2166 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 652591 T2166 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 652592 T2166 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 652592 T2166 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 652592 T2166 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 652592 T2166 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 652592 T2166 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 652593 T2166 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 652593 T2166 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 652593 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 652599 T2166 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 652601 T2166 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55834/solr
[junit4:junit4] 2> 652601 T2166 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 652603 T2166 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 652615 T2222 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@dca0175 name:ZooKeeperConnection Watcher:127.0.0.1:55834 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 652616 T2166 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 652620 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 652628 T2166 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 652632 T2224 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6d6a6a76 name:ZooKeeperConnection Watcher:127.0.0.1:55834/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 652632 T2166 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 652640 T2166 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 653435 T2189 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 653436 T2189 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55853__qvl%2Fu",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55853/_qvl/u"}
[junit4:junit4] 2> 653445 T2208 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> 653445 T2224 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> 653446 T2195 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> 653447 T2188 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> 653596 T2166 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55862__qvl%2Fu
[junit4:junit4] 2> 653599 T2166 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55862__qvl%2Fu
[junit4:junit4] 2> 653607 T2208 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 653607 T2208 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> 653607 T2224 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 653607 T2224 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> 653607 T2195 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 653608 T2195 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> 653607 T2188 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 653609 T2188 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> 653621 T2225 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 653621 T2225 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 654924 T2189 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 654925 T2189 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55862__qvl%2Fu",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55862/_qvl/u"}
[junit4:junit4] 2> 654925 T2189 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 654925 T2189 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 654961 T2208 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> 654961 T2188 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> 654961 T2224 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> 654961 T2195 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> 655585 T2225 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty2-1371651852318\collection1
[junit4:junit4] 2> 655585 T2225 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 655586 T2225 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 655586 T2225 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 655589 T2225 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty2-1371651852318\collection1\'
[junit4:junit4] 2> 655590 T2225 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1371651852318/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 655592 T2225 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1371651852318/collection1/lib/README' to classloader
[junit4:junit4] 2> 655645 T2225 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 655709 T2225 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 655712 T2225 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 655716 T2225 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 656350 T2225 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 656364 T2225 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 656370 T2225 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 656390 T2225 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 656394 T2225 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 656398 T2225 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 656401 T2225 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 656402 T2225 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 656402 T2225 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 656403 T2225 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 656403 T2225 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 656403 T2225 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 656404 T2225 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty2-1371651852318\collection1\, dataDir=.\org.apache.solr.cloud.SyncSliceTest-1371651843140/jetty2\
[junit4:junit4] 2> 656404 T2225 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a80dee3
[junit4:junit4] 2> 656404 T2225 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 656405 T2225 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2
[junit4:junit4] 2> 656406 T2225 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.SyncSliceTest-1371651843140/jetty2\index/
[junit4:junit4] 2> 656408 T2225 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 656408 T2225 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2\index
[junit4:junit4] 2> 656423 T2225 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ba9c044; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 656423 T2225 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 656429 T2225 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 656429 T2225 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 656430 T2225 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 656431 T2225 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 656432 T2225 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 656432 T2225 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 656432 T2225 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 656433 T2225 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 656433 T2225 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 656443 T2225 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 656456 T2225 oass.SolrIndexSearcher.<init> Opening Searcher@144c61b3 main
[junit4:junit4] 2> 656460 T2225 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 656460 T2225 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 656466 T2226 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@144c61b3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 656468 T2225 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 656468 T2225 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55862/_qvl/u collection:collection1 shard:shard1
[junit4:junit4] 2> 656476 T2225 oasc.ZkController.register We are http://127.0.0.1:55862/_qvl/u/collection1/ and leader is http://127.0.0.1:55853/_qvl/u/collection1/
[junit4:junit4] 2> 656476 T2225 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55862/_qvl/u
[junit4:junit4] 2> 656476 T2225 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 656476 T2225 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C5082 name=collection1 org.apache.solr.core.SolrCore@3f5f476b url=http://127.0.0.1:55862/_qvl/u/collection1 node=127.0.0.1:55862__qvl%2Fu C5082_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:55862__qvl%2Fu, base_url=http://127.0.0.1:55862/_qvl/u}
[junit4:junit4] 2> 656478 T2227 C5082 P55862 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 656478 T2227 C5082 P55862 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 656479 T2227 C5082 P55862 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 656479 T2227 C5082 P55862 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 656479 T2225 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 656481 T2227 C5082 P55862 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 656483 T2166 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 656484 T2166 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 656484 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 656507 T2199 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 656899 T2166 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 656903 T2166 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55872
[junit4:junit4] 2> 656905 T2166 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 656905 T2166 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 656905 T2166 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty3-1371651856727
[junit4:junit4] 2> 656906 T2166 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty3-1371651856727\solr.xml
[junit4:junit4] 2> 656906 T2166 oasc.CoreContainer.<init> New CoreContainer 1503849422
[junit4:junit4] 2> 656906 T2166 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty3-1371651856727\'
[junit4:junit4] 2> 656906 T2166 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty3-1371651856727\'
[junit4:junit4] 2> 657004 T2166 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 657005 T2166 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 657005 T2166 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 657005 T2166 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 657005 T2166 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 657006 T2166 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 657007 T2166 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 657007 T2166 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 657007 T2166 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 657007 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 657015 T2166 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 657015 T2166 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55834/solr
[junit4:junit4] 2> 657015 T2166 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 657018 T2166 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 657034 T2239 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@66ee1c26 name:ZooKeeperConnection Watcher:127.0.0.1:55834 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 657035 T2166 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 657039 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 657040 T2168 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f5cd224500009, 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:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 657046 T2166 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 657051 T2241 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6709a112 name:ZooKeeperConnection Watcher:127.0.0.1:55834/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 657052 T2166 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 657061 T2166 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 657914 T2189 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 657917 T2189 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55862__qvl%2Fu",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55862/_qvl/u"}
[junit4:junit4] 2> 657943 T2241 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> 657946 T2195 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> 657948 T2224 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> 657948 T2208 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> 657950 T2188 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> 658046 T2166 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55872__qvl%2Fu
[junit4:junit4] 2> 658051 T2166 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55872__qvl%2Fu
[junit4:junit4] 2> 658063 T2241 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 658064 T2241 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> 658065 T2195 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 658065 T2195 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> 658066 T2208 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 658067 T2208 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> 658067 T2188 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 658069 T2188 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> 658067 T2224 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 658069 T2224 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> 658087 T2242 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 658087 T2242 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 658467 T2199 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 658467 T2199 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=3&state=recovering&nodeName=127.0.0.1:55862__qvl%252Fu&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1960
[junit4:junit4] 2> 659436 T2189 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 659437 T2189 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55872__qvl%2Fu",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55872/_qvl/u"}
[junit4:junit4] 2> 659437 T2189 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 659437 T2189 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 659450 T2208 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> 659450 T2195 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> 659450 T2241 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> 659450 T2224 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> 659450 T2188 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> 660049 T2242 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty3-1371651856727\collection1
[junit4:junit4] 2> 660049 T2242 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 660050 T2242 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 660051 T2242 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 660053 T2242 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty3-1371651856727\collection1\'
[junit4:junit4] 2> 660054 T2242 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1371651856727/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 660055 T2242 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1371651856727/collection1/lib/README' to classloader
[junit4:junit4] 2> 660102 T2242 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 660170 T2242 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 660174 T2242 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 660180 T2242 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C5083 name=collection1 org.apache.solr.core.SolrCore@3f5f476b url=http://127.0.0.1:55862/_qvl/u/collection1 node=127.0.0.1:55862__qvl%2Fu C5083_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:55862__qvl%2Fu, base_url=http://127.0.0.1:55862/_qvl/u}
[junit4:junit4] 2> 660428 T2227 C5083 P55862 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:55853/_qvl/u/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 660428 T2227 C5083 P55862 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:55862/_qvl/u START replicas=[http://127.0.0.1:55853/_qvl/u/collection1/] nUpdates=100
[junit4:junit4] 2> 660429 T2227 C5083 P55862 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 660430 T2227 C5083 P55862 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 660430 T2227 C5083 P55862 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 660430 T2227 C5083 P55862 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 660430 T2227 C5083 P55862 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 660431 T2227 C5083 P55862 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:55853/_qvl/u/collection1/. core=collection1
[junit4:junit4] 2> 660431 T2227 C5083 P55862 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C5084 name=collection1 org.apache.solr.core.SolrCore@79aed9 url=http://127.0.0.1:55853/_qvl/u/collection1 node=127.0.0.1:55853__qvl%2Fu C5084_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55853__qvl%2Fu, base_url=http://127.0.0.1:55853/_qvl/u, leader=true}
[junit4:junit4] 2> 660443 T2202 C5084 P55853 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 660444 T2202 C5084 P55853 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 660451 T2202 C5084 P55853 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 660452 T2202 C5084 P55853 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 660471 T2202 C5084 P55853 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 660471 T2202 C5084 P55853 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 660474 T2202 C5084 P55853 oass.SolrIndexSearcher.<init> Opening Searcher@3df3e636 realtime
[junit4:junit4] 2> 660474 T2202 C5084 P55853 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 660474 T2202 C5084 P55853 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 30
[junit4:junit4] 2> 660475 T2227 C5083 P55862 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 660475 T2227 C5083 P55862 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 660509 T2204 C5084 P55853 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 660509 T2204 C5084 P55853 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 660510 T2227 C5083 P55862 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 660510 T2227 C5083 P55862 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 660510 T2227 C5083 P55862 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 660516 T2200 C5084 P55853 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=3
[junit4:junit4] 2> 660517 T2227 C5083 P55862 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 660519 T2227 C5083 P55862 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2\index.20130619162420737
[junit4:junit4] 2> 660520 T2227 C5083 P55862 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2\index.20130619162420737 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4a45fc1c; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 660524 T2201 C5084 P55853 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 660525 T2227 C5083 P55862 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 660531 T2227 C5083 P55862 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 660531 T2227 C5083 P55862 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 660539 T2227 C5083 P55862 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ba9c044; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ba9c044; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 660540 T2227 C5083 P55862 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 660541 T2227 C5083 P55862 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 660542 T2227 C5083 P55862 oass.SolrIndexSearcher.<init> Opening Searcher@3a5980f8 main
[junit4:junit4] 2> 660543 T2226 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3a5980f8 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 660544 T2227 C5083 P55862 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2\index.20130619162420737 [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2\index.20130619162420737;done=true>>]
[junit4:junit4] 2> 660544 T2227 C5083 P55862 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2\index.20130619162420737
[junit4:junit4] 2> 660544 T2227 C5083 P55862 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2\index.20130619162420737
[junit4:junit4] 2> 660545 T2227 C5083 P55862 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 660545 T2227 C5083 P55862 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 660545 T2227 C5083 P55862 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 660545 T2227 C5083 P55862 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 660548 T2227 C5083 P55862 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 660844 T2242 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 660854 T2242 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 660858 T2242 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 660879 T2242 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 660892 T2242 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 660898 T2242 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 660900 T2242 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 660900 T2242 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 660900 T2242 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 660902 T2242 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 660902 T2242 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 660902 T2242 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 660902 T2242 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty3-1371651856727\collection1\, dataDir=.\org.apache.solr.cloud.SyncSliceTest-1371651843140/jetty3\
[junit4:junit4] 2> 660902 T2242 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a80dee3
[junit4:junit4] 2> 660902 T2242 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 660903 T2242 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3
[junit4:junit4] 2> 660903 T2242 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.SyncSliceTest-1371651843140/jetty3\index/
[junit4:junit4] 2> 660905 T2242 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 660905 T2242 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3\index
[junit4:junit4] 2> 660921 T2242 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec922c0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 660921 T2242 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 660924 T2242 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 660924 T2242 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 660925 T2242 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 660926 T2242 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 660927 T2242 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 660927 T2242 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 660928 T2189 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 660929 T2189 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55862__qvl%2Fu",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55862/_qvl/u"}
[junit4:junit4] 2> 660934 T2242 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 660935 T2242 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 660936 T2242 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 660939 T2208 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> 660939 T2188 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> 660940 T2224 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> 660940 T2241 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> 660940 T2195 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> 660948 T2242 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 660959 T2242 oass.SolrIndexSearcher.<init> Opening Searcher@1774a84b main
[junit4:junit4] 2> 660962 T2242 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 660963 T2242 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 660968 T2245 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1774a84b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 660968 T2242 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 660968 T2242 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55872/_qvl/u collection:collection1 shard:shard1
[junit4:junit4] 2> 660974 T2242 oasc.ZkController.register We are http://127.0.0.1:55872/_qvl/u/collection1/ and leader is http://127.0.0.1:55853/_qvl/u/collection1/
[junit4:junit4] 2> 660974 T2242 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55872/_qvl/u
[junit4:junit4] 2> 660974 T2242 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 660974 T2242 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C5085 name=collection1 org.apache.solr.core.SolrCore@56a5e4 url=http://127.0.0.1:55872/_qvl/u/collection1 node=127.0.0.1:55872__qvl%2Fu C5085_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:55872__qvl%2Fu, base_url=http://127.0.0.1:55872/_qvl/u}
[junit4:junit4] 2> 660975 T2246 C5085 P55872 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 660975 T2246 C5085 P55872 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 660975 T2246 C5085 P55872 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 660976 T2246 C5085 P55872 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 660976 T2242 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 660979 T2246 C5085 P55872 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 660980 T2166 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 660980 T2166 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 660980 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 660988 T2202 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 661372 T2166 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 661375 T2166 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:55885
[junit4:junit4] 2> 661377 T2166 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 661377 T2166 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 661378 T2166 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty4-1371651861206
[junit4:junit4] 2> 661378 T2166 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty4-1371651861206\solr.xml
[junit4:junit4] 2> 661378 T2166 oasc.CoreContainer.<init> New CoreContainer 207334096
[junit4:junit4] 2> 661379 T2166 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty4-1371651861206\'
[junit4:junit4] 2> 661379 T2166 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty4-1371651861206\'
[junit4:junit4] 2> 661480 T2166 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 661480 T2166 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 661480 T2166 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 661481 T2166 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 661481 T2166 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 661482 T2166 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 661482 T2166 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 661482 T2166 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 661482 T2166 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 661483 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 661490 T2166 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 661491 T2166 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55834/solr
[junit4:junit4] 2> 661491 T2166 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 661494 T2166 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 661511 T2258 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4288dd79 name:ZooKeeperConnection Watcher:127.0.0.1:55834 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 661512 T2166 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 661518 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 661526 T2166 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 661530 T2260 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3adbb6b name:ZooKeeperConnection Watcher:127.0.0.1:55834/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 661531 T2166 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 661541 T2166 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 662423 T2189 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 662424 T2189 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55872__qvl%2Fu",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55872/_qvl/u"}
[junit4:junit4] 2> 662435 T2241 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> 662436 T2208 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> 662437 T2260 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> 662436 T2195 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> 662439 T2224 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> 662439 T2188 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> 662527 T2166 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55885__qvl%2Fu
[junit4:junit4] 2> 662530 T2166 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55885__qvl%2Fu
[junit4:junit4] 2> 662534 T2260 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> 662537 T2208 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 662537 T2208 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> 662537 T2188 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 662538 T2188 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> 662538 T2224 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 662538 T2224 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> 662539 T2241 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 662540 T2241 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> 662541 T2195 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 662541 T2195 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> 662542 T2260 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 662553 T2261 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 662553 T2261 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 662966 T2202 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 662966 T2202 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:55872__qvl%252Fu&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1978
[junit4:junit4] 2> 664036 T2189 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 664037 T2189 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55885__qvl%2Fu",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55885/_qvl/u"}
[junit4:junit4] 2> 664037 T2189 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 664037 T2189 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 664062 T2241 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> 664063 T2260 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> 664063 T2224 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> 664063 T2208 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> 664063 T2188 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> 664065 T2195 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> 664692 T2261 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty4-1371651861206\collection1
[junit4:junit4] 2> 664692 T2261 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 664693 T2261 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 664693 T2261 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 664696 T2261 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty4-1371651861206\collection1\'
[junit4:junit4] 2> 664697 T2261 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1371651861206/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 664698 T2261 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1371651861206/collection1/lib/README' to classloader
[junit4:junit4] 2> 664759 T2261 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 664858 T2261 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 664862 T2261 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 664868 T2261 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C5086 name=collection1 org.apache.solr.core.SolrCore@56a5e4 url=http://127.0.0.1:55872/_qvl/u/collection1 node=127.0.0.1:55872__qvl%2Fu C5086_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:55872__qvl%2Fu, base_url=http://127.0.0.1:55872/_qvl/u}
[junit4:junit4] 2> 665124 T2246 C5086 P55872 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:55853/_qvl/u/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 665124 T2246 C5086 P55872 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:55872/_qvl/u START replicas=[http://127.0.0.1:55853/_qvl/u/collection1/] nUpdates=100
[junit4:junit4] 2> 665124 T2246 C5086 P55872 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 665124 T2246 C5086 P55872 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 665125 T2246 C5086 P55872 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 665125 T2246 C5086 P55872 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 665125 T2246 C5086 P55872 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 665125 T2246 C5086 P55872 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:55853/_qvl/u/collection1/. core=collection1
[junit4:junit4] 2> 665126 T2246 C5086 P55872 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C5087 name=collection1 org.apache.solr.core.SolrCore@79aed9 url=http://127.0.0.1:55853/_qvl/u/collection1 node=127.0.0.1:55853__qvl%2Fu C5087_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55853__qvl%2Fu, base_url=http://127.0.0.1:55853/_qvl/u, leader=true}
[junit4:junit4] 2> 665131 T2201 C5087 P55853 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 665135 T2199 C5087 P55853 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 665152 T2201 C5087 P55853 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 665153 T2201 C5087 P55853 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 665155 T2201 C5087 P55853 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 665155 T2201 C5087 P55853 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4] 2> 665156 T2246 C5086 P55872 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 665156 T2246 C5086 P55872 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 665158 T2204 C5087 P55853 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 665159 T2246 C5086 P55872 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 665159 T2246 C5086 P55872 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 665159 T2246 C5086 P55872 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 665165 T2200 C5087 P55853 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=2
[junit4:junit4] 2> 665165 T2246 C5086 P55872 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 665167 T2246 C5086 P55872 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3\index.20130619162425385
[junit4:junit4] 2> 665168 T2246 C5086 P55872 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3\index.20130619162425385 lockFactory=org.apache.lucene.store.NativeFSLockFactory@d42771b; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 665171 T2202 C5087 P55853 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/replication params={file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 2> 665173 T2246 C5086 P55872 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 665178 T2246 C5086 P55872 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 665178 T2246 C5086 P55872 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 665186 T2246 C5086 P55872 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec922c0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec922c0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 665186 T2246 C5086 P55872 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 665186 T2246 C5086 P55872 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 665189 T2246 C5086 P55872 oass.SolrIndexSearcher.<init> Opening Searcher@429688db main
[junit4:junit4] 2> 665189 T2245 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@429688db main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 665190 T2246 C5086 P55872 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3\index.20130619162425385 [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3\index.20130619162425385;done=true>>]
[junit4:junit4] 2> 665190 T2246 C5086 P55872 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3\index.20130619162425385
[junit4:junit4] 2> 665190 T2246 C5086 P55872 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3\index.20130619162425385
[junit4:junit4] 2> 665191 T2246 C5086 P55872 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 665191 T2246 C5086 P55872 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 665191 T2246 C5086 P55872 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 665191 T2246 C5086 P55872 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 665195 T2246 C5086 P55872 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 665547 T2261 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 665557 T2261 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 665561 T2261 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 665580 T2261 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 665594 T2261 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 665600 T2261 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 665602 T2261 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 665602 T2261 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 665602 T2261 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 665604 T2261 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 665604 T2261 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 665604 T2261 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 665604 T2261 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty4-1371651861206\collection1\, dataDir=.\org.apache.solr.cloud.SyncSliceTest-1371651843140/jetty4\
[junit4:junit4] 2> 665605 T2261 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a80dee3
[junit4:junit4] 2> 665605 T2261 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 665605 T2261 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4
[junit4:junit4] 2> 665607 T2261 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.SyncSliceTest-1371651843140/jetty4\index/
[junit4:junit4] 2> 665608 T2261 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 665608 T2261 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4\index
[junit4:junit4] 2> 665618 T2261 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e13630b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 665618 T2261 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 665622 T2261 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 665623 T2261 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 665623 T2261 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 665624 T2261 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 665624 T2261 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 665624 T2261 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 665629 T2261 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 665631 T2261 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 665631 T2261 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 665642 T2261 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 665651 T2261 oass.SolrIndexSearcher.<init> Opening Searcher@19fceba3 main
[junit4:junit4] 2> 665654 T2261 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 665654 T2261 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 665660 T2264 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@19fceba3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 665661 T2261 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 665661 T2261 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55885/_qvl/u collection:collection1 shard:shard1
[junit4:junit4] 2> 665667 T2261 oasc.ZkController.register We are http://127.0.0.1:55885/_qvl/u/collection1/ and leader is http://127.0.0.1:55853/_qvl/u/collection1/
[junit4:junit4] 2> 665667 T2261 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55885/_qvl/u
[junit4:junit4] 2> 665667 T2261 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 665667 T2261 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C5088 name=collection1 org.apache.solr.core.SolrCore@6ddbe7e6 url=http://127.0.0.1:55885/_qvl/u/collection1 node=127.0.0.1:55885__qvl%2Fu C5088_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:55885__qvl%2Fu, base_url=http://127.0.0.1:55885/_qvl/u}
[junit4:junit4] 2> 665669 T2265 C5088 P55885 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 665669 T2265 C5088 P55885 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 665669 T2265 C5088 P55885 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 665669 T2265 C5088 P55885 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 665669 T2261 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 665672 T2265 C5088 P55885 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 665673 T2166 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 665674 T2166 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 665674 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 665681 T2166 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 665682 T2201 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 665683 T2166 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 665683 T2166 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 665684 T2166 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 665701 T2189 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 665702 T2189 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55872__qvl%2Fu",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55872/_qvl/u"}
[junit4:junit4] 2> 665709 T2189 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55885__qvl%2Fu",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55885/_qvl/u"}
[junit4:junit4] 2> 665723 T2241 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> 665724 T2188 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> 665725 T2260 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> 665724 T2208 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> 665726 T2224 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> 665724 T2195 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> 666760 T2201 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 666760 T2201 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:55885__qvl%252Fu&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1078
[junit4:junit4] 2> 666763 T2166 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 667844 T2166 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C5088_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:55885__qvl%2Fu, base_url=http://127.0.0.1:55885/_qvl/u}
[junit4:junit4] 2> 668917 T2265 C5088 P55885 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:55853/_qvl/u/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 668917 T2265 C5088 P55885 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:55885/_qvl/u START replicas=[http://127.0.0.1:55853/_qvl/u/collection1/] nUpdates=100
[junit4:junit4] 2> 668918 T2265 C5088 P55885 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 668918 T2265 C5088 P55885 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 668918 T2265 C5088 P55885 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 668918 T2265 C5088 P55885 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 668918 T2265 C5088 P55885 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 668918 T2265 C5088 P55885 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:55853/_qvl/u/collection1/. core=collection1
[junit4:junit4] 2> 668918 T2265 C5088 P55885 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C5089 name=collection1 org.apache.solr.core.SolrCore@79aed9 url=http://127.0.0.1:55853/_qvl/u/collection1 node=127.0.0.1:55853__qvl%2Fu C5089_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55853__qvl%2Fu, base_url=http://127.0.0.1:55853/_qvl/u, leader=true}
[junit4:junit4] 2> 668921 T2201 C5089 P55853 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 668925 T2166 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 668926 T2202 C5089 P55853 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 668941 T2202 C5089 P55853 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 668942 T2202 C5089 P55853 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 668943 T2202 C5089 P55853 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 668944 T2202 C5089 P55853 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 18
[junit4:junit4] 2> 668945 T2265 C5088 P55885 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 668945 T2265 C5088 P55885 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 668947 T2203 C5089 P55853 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 668948 T2265 C5088 P55885 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 668948 T2265 C5088 P55885 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 668948 T2265 C5088 P55885 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 668952 T2204 C5089 P55853 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=1
[junit4:junit4] 2> 668953 T2265 C5088 P55885 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 668956 T2265 C5088 P55885 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4\index.20130619162429174
[junit4:junit4] 2> 668957 T2265 C5088 P55885 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4\index.20130619162429174 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ec8d6c0; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 668961 T2201 C5089 P55853 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/replication params={file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> 668962 T2265 C5088 P55885 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 668967 T2265 C5088 P55885 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 668967 T2265 C5088 P55885 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 668974 T2265 C5088 P55885 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e13630b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e13630b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 668975 T2265 C5088 P55885 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 668975 T2265 C5088 P55885 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 668977 T2265 C5088 P55885 oass.SolrIndexSearcher.<init> Opening Searcher@5589c1c2 main
[junit4:junit4] 2> 668978 T2264 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5589c1c2 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 668978 T2265 C5088 P55885 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4\index.20130619162429174 [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4\index.20130619162429174;done=true>>]
[junit4:junit4] 2> 668978 T2265 C5088 P55885 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4\index.20130619162429174
[junit4:junit4] 2> 668978 T2265 C5088 P55885 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4\index.20130619162429174
[junit4:junit4] 2> 668980 T2265 C5088 P55885 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 668980 T2265 C5088 P55885 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 668980 T2265 C5088 P55885 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 668980 T2265 C5088 P55885 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 668983 T2265 C5088 P55885 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 670007 T2166 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 670598 T2189 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 670600 T2189 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55885__qvl%2Fu",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55885/_qvl/u"}
[junit4:junit4] 2> 670617 T2241 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> 670619 T2208 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> 670619 T2188 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> 670619 T2195 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> 670620 T2260 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> 670620 T2224 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> 671089 T2166 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 671090 T2166 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C5090 name=collection1 org.apache.solr.core.SolrCore@4f450f1b url=http://127.0.0.1:55841/_qvl/u/collection1 node=127.0.0.1:55841__qvl%2Fu C5090_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:55841__qvl%2Fu, base_url=http://127.0.0.1:55841/_qvl/u, leader=true}
[junit4:junit4] 2> 671106 T2181 C5090 P55841 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 671113 T2181 C5090 P55841 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b52e997; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 671114 T2181 C5090 P55841 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 671123 T2181 C5090 P55841 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b52e997; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b52e997; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 671124 T2181 C5090 P55841 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 671128 T2181 C5090 P55841 oass.SolrIndexSearcher.<init> Opening Searcher@3a8cdb17 main
[junit4:junit4] 2> 671128 T2181 C5090 P55841 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 671129 T2192 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3a8cdb17 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 671130 T2181 C5090 P55841 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4] 2> C5088_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55885__qvl%2Fu, base_url=http://127.0.0.1:55885/_qvl/u}
[junit4:junit4] 2> 671146 T2254 C5088 P55885 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:55853/_qvl/u/collection1/, StdNode: http://127.0.0.1:55862/_qvl/u/collection1/, StdNode: http://127.0.0.1:55872/_qvl/u/collection1/, StdNode: http://127.0.0.1:55885/_qvl/u/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 671153 T2201 C5089 P55853 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 671154 T2255 C5088 P55885 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 671167 T2255 C5088 P55885 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e13630b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e13630b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 671167 T2255 C5088 P55885 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 671170 T2201 C5089 P55853 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 671170 T2201 C5089 P55853 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 671174 T2201 C5089 P55853 oass.SolrIndexSearcher.<init> Opening Searcher@3161866 main
[junit4:junit4] 2> 671175 T2201 C5089 P55853 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 671175 T2255 C5088 P55885 oass.SolrIndexSearcher.<init> Opening Searcher@2f00016f main
[junit4:junit4] 2> 671175 T2255 C5088 P55885 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 671177 T2210 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3161866 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 671177 T2201 C5089 P55853 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4] 2> 671177 T2264 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2f00016f main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 671178 T2255 C5088 P55885 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4] 2> ASYNC NEW_CORE C5091 name=collection1 org.apache.solr.core.SolrCore@56a5e4 url=http://127.0.0.1:55872/_qvl/u/collection1 node=127.0.0.1:55872__qvl%2Fu C5091_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55872__qvl%2Fu, base_url=http://127.0.0.1:55872/_qvl/u}
[junit4:junit4] 2> 671184 T2235 C5091 P55872 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C5092 name=collection1 org.apache.solr.core.SolrCore@3f5f476b url=http://127.0.0.1:55862/_qvl/u/collection1 node=127.0.0.1:55862__qvl%2Fu C5092_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55862__qvl%2Fu, base_url=http://127.0.0.1:55862/_qvl/u}
[junit4:junit4] 2> 671185 T2217 C5092 P55862 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 671193 T2235 C5091 P55872 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec922c0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec922c0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 671193 T2235 C5091 P55872 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 671194 T2217 C5092 P55862 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ba9c044; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ba9c044; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 671195 T2217 C5092 P55862 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 671199 T2217 C5092 P55862 oass.SolrIndexSearcher.<init> Opening Searcher@751aeb55 main
[junit4:junit4] 2> 671199 T2217 C5092 P55862 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 671201 T2226 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@751aeb55 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 671201 T2217 C5092 P55862 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 16
[junit4:junit4] 2> 671203 T2235 C5091 P55872 oass.SolrIndexSearcher.<init> Opening Searcher@701e295d main
[junit4:junit4] 2> 671203 T2235 C5091 P55872 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 671204 T2245 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@701e295d main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 671204 T2235 C5091 P55872 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 21
[junit4:junit4] 2> 671205 T2254 C5088 P55885 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 59
[junit4:junit4] 2> 671206 T2166 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 671209 T2200 C5089 P55853 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 671211 T2218 C5092 P55862 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 671214 T2236 C5091 P55872 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 671216 T2256 C5088 P55885 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 673382 T2181 C5090 P55841 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438281235007799296)} 0 6
[junit4:junit4] 2> 673398 T2218 C5092 P55862 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={update.distrib=FROMLEADER&_version_=-1438281235017236480&update.from=http://127.0.0.1:55853/_qvl/u/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438281235017236480)} 0 1
[junit4:junit4] 2> 673401 T2236 C5091 P55872 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={update.distrib=FROMLEADER&_version_=-1438281235017236480&update.from=http://127.0.0.1:55853/_qvl/u/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438281235017236480)} 0 5
[junit4:junit4] 2> 673402 T2256 C5088 P55885 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={update.distrib=FROMLEADER&_version_=-1438281235017236480&update.from=http://127.0.0.1:55853/_qvl/u/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438281235017236480)} 0 6
[junit4:junit4] 2> 673403 T2200 C5089 P55853 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438281235017236480)} 0 18
[junit4:junit4] 2> 673408 T2182 C5090 P55841 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={wt=javabin&version=2} {add=[0 (1438281235039256576)]} 0 2
[junit4:junit4] 2> 673421 T2251 C5088 P55885 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={distrib.from=http://127.0.0.1:55853/_qvl/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438281235047645184)]} 0 2
[junit4:junit4] 2> 673421 T2220 C5092 P55862 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={distrib.from=http://127.0.0.1:55853/_qvl/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438281235047645184)]} 0 2
[junit4:junit4] 2> 673423 T2237 C5091 P55872 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={distrib.from=http://127.0.0.1:55853/_qvl/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438281235047645184)]} 0 2
[junit4:junit4] 2> 673424 T2202 C5089 P55853 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={distrib.from=http://127.0.0.1:55862/_qvl/u/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1438281235047645184)]} 0 10
[junit4:junit4] 2> 673425 T2219 C5092 P55862 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={wt=javabin&version=2} {add=[0]} 0 14
[junit4:junit4] 2> 673428 T2183 C5090 P55841 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={wt=javabin&version=2} {add=[1 (1438281235061276672)]} 0 1
[junit4:junit4] 2> 673439 T2215 C5092 P55862 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={distrib.from=http://127.0.0.1:55853/_qvl/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438281235068616704)]} 0 1
[junit4:junit4] 2> 673439 T2252 C5088 P55885 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={distrib.from=http://127.0.0.1:55853/_qvl/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438281235068616704)]} 0 1
[junit4:junit4] 2> 673440 T2233 C5091 P55872 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={distrib.from=http://127.0.0.1:55853/_qvl/u/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438281235068616704)]} 0 0
[junit4:junit4] 2> 673442 T2199 C5089 P55853 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={distrib.from=http://127.0.0.1:55872/_qvl/u/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1438281235068616704)]} 0 8
[junit4:junit4] 2> 673442 T2232 C5091 P55872 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={wt=javabin&version=2} {add=[1]} 0 11
[junit4:junit4] 2> 673446 T2184 C5090 P55841 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={wt=javabin&version=2} {add=[2 (1438281235080151040)]} 0 1
[junit4:junit4] 2> 673452 T2203 C5089 P55853 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:55862/_qvl/u/collection1/]
[junit4:junit4] 2> 673452 T2203 C5089 P55853 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:55862/_qvl/u/collection1/ against:[http://127.0.0.1:55862/_qvl/u/collection1/] result:true
[junit4:junit4] 2> 673452 T2203 C5089 P55853 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:55872/_qvl/u/collection1/ against:[http://127.0.0.1:55862/_qvl/u/collection1/] result:false
[junit4:junit4] 2> 673452 T2203 C5089 P55853 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:55885/_qvl/u/collection1/ against:[http://127.0.0.1:55862/_qvl/u/collection1/] result:false
[junit4:junit4] 2> 673458 T2235 C5091 P55872 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={distrib.from=http://127.0.0.1:55853/_qvl/u/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:55862/_qvl/u/collection1/&wt=javabin&version=2} {add=[2 (1438281235088539648)]} 0 1
[junit4:junit4] 2> 673459 T2253 C5088 P55885 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={distrib.from=http://127.0.0.1:55853/_qvl/u/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:55862/_qvl/u/collection1/&wt=javabin&version=2} {add=[2 (1438281235088539648)]} 0 1
[junit4:junit4] 2> 673459 T2203 C5089 P55853 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={distrib.from=http://127.0.0.1:55872/_qvl/u/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:55862/_qvl/u/collection1/&wt=javabin&version=2} {add=[2 (1438281235088539648)]} 0 7
[junit4:junit4] 2> 673460 T2234 C5091 P55872 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={test.distrib.skip.servers=http://127.0.0.1:55862/_qvl/u/collection1/&wt=javabin&version=2} {add=[2]} 0 11
[junit4:junit4] 2> 673464 T2179 C5090 P55841 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={wt=javabin&version=2} {add=[3 (1438281235099025408)]} 0 1
[junit4:junit4] 2> 673467 T2204 C5089 P55853 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:55862/_qvl/u/collection1/, http://127.0.0.1:55872/_qvl/u/collection1/]
[junit4:junit4] 2> 673468 T2204 C5089 P55853 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:55862/_qvl/u/collection1/ against:[http://127.0.0.1:55862/_qvl/u/collection1/, http://127.0.0.1:55872/_qvl/u/collection1/] result:true
[junit4:junit4] 2> 673468 T2204 C5089 P55853 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:55872/_qvl/u/collection1/ against:[http://127.0.0.1:55862/_qvl/u/collection1/, http://127.0.0.1:55872/_qvl/u/collection1/] result:true
[junit4:junit4] 2> 673469 T2204 C5089 P55853 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:55885/_qvl/u/collection1/ against:[http://127.0.0.1:55862/_qvl/u/collection1/, http://127.0.0.1:55872/_qvl/u/collection1/] result:false
[junit4:junit4] 2> 673473 T2255 C5088 P55885 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={distrib.from=http://127.0.0.1:55853/_qvl/u/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:55862/_qvl/u/collection1/&wt=javabin&version=2} {add=[3 (1438281235105316864)]} 0 1
[junit4:junit4] 2> 673474 T2204 C5089 P55853 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={test.distrib.skip.servers=http://127.0.0.1:55862/_qvl/u/collection1/&test.distrib.skip.servers=http://127.0.0.1:55872/_qvl/u/collection1/&wt=javabin&version=2} {add=[3 (1438281235105316864)]} 0 7
[junit4:junit4] 2> 673477 T2180 C5090 P55841 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 673513 T2180 C5090 P55841 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b52e997; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b52e997; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 673513 T2180 C5090 P55841 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 673521 T2180 C5090 P55841 oass.SolrIndexSearcher.<init> Opening Searcher@481158b main
[junit4:junit4] 2> 673522 T2180 C5090 P55841 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 673523 T2192 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@481158b main{StandardDirectoryReader(segments_3:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 673523 T2180 C5090 P55841 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 46
[junit4:junit4] 2> 673526 T2254 C5088 P55885 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:55853/_qvl/u/collection1/, StdNode: http://127.0.0.1:55862/_qvl/u/collection1/, StdNode: http://127.0.0.1:55872/_qvl/u/collection1/, StdNode: http://127.0.0.1:55885/_qvl/u/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 673529 T2201 C5089 P55853 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 673530 T2236 C5091 P55872 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 673529 T2216 C5092 P55862 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 673551 T2256 C5088 P55885 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 673596 T2201 C5089 P55853 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@55404273; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 673599 T2201 C5089 P55853 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> ASYNC NEW_CORE C5093 name=collection1 org.apache.solr.core.SolrCore@79aed9 url=http://127.0.0.1:55853/_qvl/u/collection1 node=127.0.0.1:55853__qvl%2Fu C5093_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55853__qvl%2Fu, base_url=http://127.0.0.1:55853/_qvl/u, leader=true}
[junit4:junit4] 2> 673624 T2201 C5093 P55853 oass.SolrIndexSearcher.<init> Opening Searcher@17f5dc73 main
[junit4:junit4] 2> 673624 T2201 C5093 P55853 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> ASYNC NEW_CORE C5094 name=collection1 org.apache.solr.core.SolrCore@6ddbe7e6 url=http://127.0.0.1:55885/_qvl/u/collection1 node=127.0.0.1:55885__qvl%2Fu C5094_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55885__qvl%2Fu, base_url=http://127.0.0.1:55885/_qvl/u}
[junit4:junit4] 2> 673625 T2256 C5094 P55885 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e13630b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4e13630b; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> ASYNC NEW_CORE C5095 name=collection1 org.apache.solr.core.SolrCore@56a5e4 url=http://127.0.0.1:55872/_qvl/u/collection1 node=127.0.0.1:55872__qvl%2Fu C5095_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55872__qvl%2Fu, base_url=http://127.0.0.1:55872/_qvl/u}
[junit4:junit4] 2> 673625 T2236 C5095 P55872 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec922c0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@ec922c0; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 673627 T2236 C5095 P55872 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 673625 T2256 C5094 P55885 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 673629 T2210 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@17f5dc73 main{StandardDirectoryReader(segments_6:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 673630 T2201 C5093 P55853 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 101
[junit4:junit4] 2> 673634 T2236 C5095 P55872 oass.SolrIndexSearcher.<init> Opening Searcher@4cccdb72 main
[junit4:junit4] 2> 673634 T2236 C5095 P55872 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 673636 T2256 C5094 P55885 oass.SolrIndexSearcher.<init> Opening Searcher@6ec2f6c6 main
[junit4:junit4] 2> 673636 T2256 C5094 P55885 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 673637 T2245 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4cccdb72 main{StandardDirectoryReader(segments_5:3:nrt _0(5.0):c3)}
[junit4:junit4] 2> 673638 T2236 C5095 P55872 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 109
[junit4:junit4] 2> 673639 T2264 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6ec2f6c6 main{StandardDirectoryReader(segments_6:3:nrt _0(5.0):c4)}
[junit4:junit4] 2> 673639 T2256 C5094 P55885 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 88
[junit4:junit4] 2> ASYNC NEW_CORE C5096 name=collection1 org.apache.solr.core.SolrCore@3f5f476b url=http://127.0.0.1:55862/_qvl/u/collection1 node=127.0.0.1:55862__qvl%2Fu C5096_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:55862__qvl%2Fu, base_url=http://127.0.0.1:55862/_qvl/u}
[junit4:junit4] 2> 673643 T2216 C5096 P55862 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ba9c044; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371651843140\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@7ba9c044; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 673643 T2216 C5096 P55862 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 673650 T2216 C5096 P55862 oass.SolrIndexSearcher.<init> Opening Searcher@2f3190c2 main
[junit4:junit4] 2> 673651 T2216 C5096 P55862 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 673651 T2226 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2f3190c2 main{StandardDirectoryReader(segments_4:3:nrt _0(5.0):c2)}
[junit4:junit4] 2> 673652 T2216 C5096 P55862 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 123
[junit4:junit4] 2> 673653 T2254 C5094 P55885 oasup.LogUpdateProcessor.finish [collection1] webapp=/_qvl/u path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 127
[junit4:junit4] 2> 673653 T2166 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 673656 T2166 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 673657 T2166 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 673659 T2200 C5093 P55853 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 673662 T2217 C5096 P55862 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=2 status=0 QTime=0
[junit4:junit4] 2> 673666 T2237 C5095 P55872 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=3 status=0 QTime=0
[junit4:junit4] 2> 673669 T2251 C5094 P55885 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=0
[junit4:junit4] 2> 673671 T2166 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 673682 T2233 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2
[junit4:junit4] 2> 673683 T2233 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 673690 T2202 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 673691 T2202 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:55853/_qvl/u/collection1/
[junit4:junit4] 2> 673691 T2202 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:55853/_qvl/u START replicas=[http://127.0.0.1:55862/_qvl/u/collection1/, http://127.0.0.1:55872/_qvl/u/collection1/, http://127.0.0.1:55885/_qvl/u/collection1/] nUpdates=100
[junit4:junit4] 2> 673695 T2218 C5096 P55862 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 673696 T2232 C5095 P55872 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 673697 T2202 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:55853/_qvl/u Received 3 versions from 127.0.0.1:55862/_qvl/u/collection1/
[junit4:junit4] 2> 673696 T2252 C5094 P55885 oasc.SolrCore.execute [collection1] webapp=/_qvl/u path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 673697 T2202 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:55853/_qvl/u Our versions are newer. ourLowThreshold=1438281235017236480 otherHigh=1438281235068616704
[junit4:junit4] 2> 673698 T2202 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:55853/_qvl/u Received 4 versions from 127.0.0.1:55872/_qvl/u/collection1/
[junit4:junit4] 2> 673698 T2202 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:55853/_qvl/u Our versions are newer. ourLowThreshold=1438281235017236480 otherHigh=1438281235088539648
[junit4:junit4] 2> 673698
[...truncated too long message...]
ove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-1371653840823\zookeeper FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-1371653840823 FAILED !!!!!
[junit4:junit4] 2> 2710615 T7513 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 2710619 T7513 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:59026 59026
[junit4:junit4] 2> 2713027 T7513 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 59033
[junit4:junit4] 2> 2713056 T7513 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 2713057 T7513 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:59026 59026
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=EB2C8B79ABA1A1E1 -Dtests.slow=true -Dtests.locale=en_IE -Dtests.timezone=America/Mexico_City -Dtests.file.encoding=Cp1252
[junit4:junit4] ERROR 72.5s | ShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:59045 returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([EB2C8B79ABA1A1E1:6ACA0561DCFEC1DD]: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.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:150)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 2713069 T7513 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=Lucene40, sim=DefaultSimilarity, locale=en_IE, timezone=America/Mexico_City
[junit4:junit4] 2> NOTE: Windows 7 6.1 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=2,threads=4,free=167440360,total=285175808
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestFieldTypeResource, AutoCommitTest, BinaryUpdateRequestHandlerTest, SpellCheckComponentTest, DocumentBuilderTest, TestSurroundQueryParser, QueryElevationComponentTest, TestFieldCollectionResource, QueryResultKeyTest, TestPHPSerializedResponseWriter, TestDefaultSimilarityFactory, TestFuzzyAnalyzedSuggestions, SuggesterTSTTest, DistributedSpellCheckComponentTest, TestTrie, TestHashPartitioner, SpellCheckCollatorTest, ConvertedLegacyTest, PreAnalyzedFieldTest, SolrCmdDistributorTest, FieldMutatingUpdateProcessorTest, ZkControllerTest, StatsComponentTest, TestSerializedLuceneMatchVersion, PathHierarchyTokenizerFactoryTest, TestFiltering, OpenCloseCoreStressTest, LoggingHandlerTest, HardAutoCommitTest, ResourceLoaderTest, TestDistributedGrouping, TestCopyFieldCollectionResource, JsonLoaderTest, TermVectorComponentTest, TestSolrXml, CachingDirectoryFactoryTest, TestUpdate, TestSystemIdResolver, TestSolr4Spatial, DirectSolrConnectionTest, TestRecovery, SuggesterFSTTest, TestSchemaResource, IndexSchemaTest, TestDefaultSearchFieldResource, TestQuerySenderListener, TestRandomFaceting, TestExtendedDismaxParser, TestElisionMultitermQuery, TestFieldTypeCollectionResource, SpellPossibilityIteratorTest, TestNumberUtils, TestDFRSimilarityFactory, SchemaVersionSpecificBehaviorTest, PrimUtilsTest, TestPluginEnable, TestSolrQueryParserDefaultOperatorResource, SolrCoreCheckLockOnStartupTest, TestPhraseSuggestions, BasicDistributedZkTest, TestIndexingPerformance, QueryEqualityTest, FastVectorHighlighterTest, ChaosMonkeyNothingIsSafeTest, StandardRequestHandlerTest, TestConfig, SolrPluginUtilsTest, UUIDFieldTest, TestLazyCores, TestQueryTypes, TestValueSourceCache, CollectionsAPIDistributedZkTest, CoreAdminHandlerTest, SyncSliceTest, TestIBSimilarityFactory, BasicZkTest, TestMultiCoreConfBootstrap, SampleTest, CacheHeaderTest, SearchHandlerTest, SliceStateUpdateTest, TestManagedSchema, CopyFieldTest, SimpleFacetsTest, TestCoreDiscovery, TestBM25SimilarityFactory, SolrCoreTest, TestLuceneMatchVersion, XsltUpdateRequestHandlerTest, TestSchemaSimilarityResource, TimeZoneUtilsTest, TestComponentsName, SimplePostToolTest, TestStressReorder, TestPostingsSolrHighlighter, DateMathParserTest, TestLRUCache, TestStressVersions, ScriptEngineTest, TestPartialUpdateDeduplication, DebugComponentTest, TestCharFilters, ShardRoutingTest, TestRTGBase, RequestHandlersTest, TestManagedSchemaFieldResource, PluginInfoTest, DefaultValueUpdateProcessorTest, IndexReaderFactoryTest, TestLFUCache, SortByFunctionTest, TestFunctionQuery, CurrencyFieldOpenExchangeTest, AnalysisAfterCoreReloadTest, SpellingQueryConverterTest, TestFaceting, TestBinaryResponseWriter, SoftAutoCommitTest, SuggesterWFSTTest, TermVectorComponentDistributedTest, TestCollationField, TestZkChroot, TestRangeQuery, FieldAnalysisRequestHandlerTest, MultiTermTest, FileUtilsTest, CircularListTest, DirectUpdateHandlerOptimizeTest, SignatureUpdateProcessorFactoryTest, IndexSchemaRuntimeFieldTest, TestShardHandlerFactory, TestLMDirichletSimilarityFactory, MoreLikeThisHandlerTest, SolrRequestParserTest, BadCopyFieldTest, TestJmxMonitoredMap, ChaosMonkeySafeLeaderTest, TestAddFieldRealTimeGet, JSONWriterTest, SystemInfoHandlerTest, LeaderElectionTest, BasicDistributedZk2Test, UnloadDistributedZkTest, OverseerTest, LeaderElectionIntegrationTest, RecoveryZkTest, FullSolrCloudDistribCmdsTest, TestReplicationHandler, ClusterStateUpdateTest, ZkSolrClientTest, TestRandomDVFaceting, ZkCLITest, ShardRoutingCustomTest, TestDistributedSearch, TestRealTimeGet, TestJoin, TestReload, DistributedTermsComponentTest, TestCoreContainer, TestGroupingSearch, PeerSyncTest, BadIndexSchemaTest, TestSort, BasicFunctionalityTest, DirectUpdateHandlerTest, TestBadConfig, OverseerCollectionProcessorTest, TestIndexSearcher, HighlighterTest, ShowFileRequestHandlerTest, DistributedQueryElevationComponentTest, CurrencyFieldXmlFileTest, SolrIndexSplitterTest, TestFoldingMultitermQuery, DocValuesTest, SuggesterTest, TestStressLucene, SpatialFilterTest, TestCSVLoader, PolyFieldTest, NoCacheHeaderTest, WordBreakSolrSpellCheckerTest, TestPseudoReturnFields, TestAtomicUpdateErrorCases, TestWordDelimiterFilterFactory, StatelessScriptUpdateProcessorFactoryTest, TestRemoteStreaming, DocValuesMultiTest, DistanceFunctionTest, TestSolrDeletionPolicy1, SolrInfoMBeanTest, IndexBasedSpellCheckerTest, LukeRequestHandlerTest, DisMaxRequestHandlerTest, TestQueryUtils, TestWriterPerf, DirectSolrSpellCheckerTest, TestReversedWildcardFilterFactory, DocumentAnalysisRequestHandlerTest, PrimitiveFieldTypeTest, TestOmitPositions, FileBasedSpellCheckerTest, TermsComponentTest, XmlUpdateRequestHandlerTest, RequiredFieldsTest, TestSolrQueryParser, TestArbitraryIndexDir, RegexBoostProcessorTest, TestJmxIntegration, ReturnFieldsTest, UpdateRequestProcessorFactoryTest, TestCSVResponseWriter, MBeansHandlerTest, QueryParsingTest, TestAnalyzedSuggestions, UniqFieldsUpdateProcessorFactoryTest, PingRequestHandlerTest, CSVRequestHandlerTest, CoreContainerCoreInitFailuresTest, HighlighterConfigTest, SOLR749Test, TestPropInject, TestPropInjectDefaults, UpdateParamsTest, AlternateDirectoryTest, TestSolrIndexConfig, TestQuerySenderNoQuery, ResponseLogComponentTest, SolrIndexConfigTest, BadComponentTest, TestStressRecovery, TestMergePolicyConfig, TestSolrDeletionPolicy2, TestDocSet, TestBinaryField, TestSearchPerf, NumericFieldsTest, MinimalSchemaTest, OutputWriterTest, ExternalFileFieldSortTest, TestSolrCoreProperties, NotRequiredUniqueKeyTest, TestCodecSupport, SynonymTokenizerTest, TestXIncludeConfig, EchoParamsTest, TestSweetSpotSimilarityFactory, TestPerFieldSimilarity, TestLMJelinekMercerSimilarityFactory, TestFastWriter, LegacyHTMLStripCharFilterTest, TestFastOutputStream, OpenExchangeRatesOrgProviderTest, URLClassifyProcessorTest, TestFastLRUCache, TestSolrXMLSerializer, TestSuggestSpellingConverter, DateFieldTest, DOMUtilTest, RAMDirectoryFactoryTest, ClusterStateTest, TestSolrJ, TestUtils, TestDocumentBuilder, ZkNodePropsTest, SliceStateTest, SolrTestCaseJ4Test, AliasIntegrationTest, ChaosMonkeyShardSplitTest, ShardSplitTest]
[junit4:junit4] Completed in 72.50s, 1 test, 1 error <<< FAILURES!
[...truncated 52 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:386: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:366: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build.xml:181: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\common-build.xml:437: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:1243: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:887: There were test failures: 297 suites, 1252 tests, 1 error, 1 failure, 18 ignored (12 assumptions)
Total time: 68 minutes 48 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0_21 -XX:+UseCompressedOops -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure