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/18 11:44:57 UTC
[JENKINS] Lucene-Solr-4.x-Windows (32bit/jdk1.7.0_21) - Build #
2903 - Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Windows/2903/
Java: 32bit/jdk1.7.0_21 -server -XX:+UseSerialGC
2 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.testDistribSearch
Error Message:
shard3 is not consistent. Got 4 from http://127.0.0.1:55008/collection1lastClient and got 2 from http://127.0.0.1:55041/collection1
Stack Trace:
java.lang.AssertionError: shard3 is not consistent. Got 4 from http://127.0.0.1:55008/collection1lastClient and got 2 from http://127.0.0.1:55041/collection1
at __randomizedtesting.SeedInfo.seed([E5D0D5F06ED66AB1:64365BE819890A8D]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
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)
REGRESSION: org.apache.solr.cloud.SyncSliceTest.testDistribSearch
Error Message:
shard1 is not consistent. Got 305 from http://127.0.0.1:53613/s_k/collection1lastClient and got 252 from http://127.0.0.1:53632/s_k/collection1
Stack Trace:
java.lang.AssertionError: shard1 is not consistent. Got 305 from http://127.0.0.1:53613/s_k/collection1lastClient and got 252 from http://127.0.0.1:53632/s_k/collection1
at __randomizedtesting.SeedInfo.seed([E5D0D5F06ED66AB1:64365BE819890A8D]: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 9434 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.SyncSliceTest
[junit4:junit4] 2> 526739 T1210 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /s_k/
[junit4:junit4] 2> 526744 T1210 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\solrtest-SyncSliceTest-1371546351362
[junit4:junit4] 2> 526747 T1210 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 526748 T1211 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 526858 T1210 oasc.ZkTestServer.run start zk server on port:53594
[junit4:junit4] 2> 526861 T1210 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 526873 T1217 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@53bbf7 name:ZooKeeperConnection Watcher:127.0.0.1:53594 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 526873 T1210 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 526873 T1210 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 526884 T1212 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f5688770c0000, 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> 526887 T1210 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 526891 T1219 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10eb6bb name:ZooKeeperConnection Watcher:127.0.0.1:53594/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 526892 T1210 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 526892 T1210 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 526900 T1210 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 526905 T1210 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 526910 T1210 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 526916 T1210 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 526917 T1210 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 526928 T1210 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 526928 T1210 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 526934 T1210 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 526934 T1210 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 526939 T1210 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 526939 T1210 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 526947 T1210 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 526947 T1210 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 526952 T1210 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 526952 T1210 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 526960 T1210 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 526961 T1210 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 526966 T1210 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 526966 T1210 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 526973 T1210 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 526973 T1210 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 527465 T1210 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 527481 T1210 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53601
[junit4:junit4] 2> 527481 T1210 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 527482 T1210 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 527482 T1210 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-controljetty-1371546351597
[junit4:junit4] 2> 527482 T1210 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-controljetty-1371546351597\solr.xml
[junit4:junit4] 2> 527482 T1210 oasc.CoreContainer.<init> New CoreContainer 2746665
[junit4:junit4] 2> 527483 T1210 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-controljetty-1371546351597\'
[junit4:junit4] 2> 527483 T1210 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-controljetty-1371546351597\'
[junit4:junit4] 2> 527607 T1210 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 527608 T1210 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 527608 T1210 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 527608 T1210 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 527608 T1210 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 527609 T1210 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 527609 T1210 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 527609 T1210 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 527609 T1210 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 527610 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 527622 T1210 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 527623 T1210 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53594/solr
[junit4:junit4] 2> 527623 T1210 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 527625 T1210 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 527640 T1230 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d27749 name:ZooKeeperConnection Watcher:127.0.0.1:53594 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 527642 T1210 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 527646 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 527655 T1210 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 527659 T1232 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@78417e name:ZooKeeperConnection Watcher:127.0.0.1:53594/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 527659 T1210 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 527663 T1210 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 527673 T1210 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 527681 T1210 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 527685 T1210 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53601_s_k
[junit4:junit4] 2> 527688 T1210 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53601_s_k
[junit4:junit4] 2> 527695 T1210 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 527709 T1210 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 527714 T1210 oasc.Overseer.start Overseer (id=89885661683515395-127.0.0.1:53601_s_k-n_0000000000) starting
[junit4:junit4] 2> 527724 T1210 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 527733 T1234 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 527735 T1210 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 527741 T1210 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 527745 T1210 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 527752 T1233 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 527766 T1235 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 527766 T1235 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 529419 T1233 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 529420 T1233 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:53601_s_k",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53601/s_k"}
[junit4:junit4] 2> 529421 T1233 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 529421 T1233 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 529435 T1232 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> 529969 T1235 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-controljetty-1371546351597\collection1
[junit4:junit4] 2> 529969 T1235 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 529971 T1235 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 529971 T1235 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 529975 T1235 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-controljetty-1371546351597\collection1\'
[junit4:junit4] 2> 529979 T1235 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1371546351597/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 529981 T1235 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-controljetty-1371546351597/collection1/lib/README' to classloader
[junit4:junit4] 2> 530073 T1235 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 530178 T1235 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 530182 T1235 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 530192 T1235 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 531047 T1235 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 531060 T1235 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 531065 T1235 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 531098 T1235 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 531104 T1235 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 531112 T1235 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 531114 T1235 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 531114 T1235 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 531114 T1235 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 531118 T1235 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 531118 T1235 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 531118 T1235 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 531157 T1235 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-controljetty-1371546351597\collection1\, dataDir=.\org.apache.solr.cloud.SyncSliceTest-1371546351361/control/data\
[junit4:junit4] 2> 531158 T1235 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2143e4
[junit4:junit4] 2> 531158 T1235 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 531159 T1235 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\control\data
[junit4:junit4] 2> 531159 T1235 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.SyncSliceTest-1371546351361/control/data\index/
[junit4:junit4] 2> 531161 T1235 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.SyncSliceTest-1371546351361\control\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 531161 T1235 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\control\data\index
[junit4:junit4] 2> 531182 T1235 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1688f5c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 531182 T1235 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 531187 T1235 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 531187 T1235 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 531188 T1235 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 531188 T1235 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 531189 T1235 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 531189 T1235 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 531189 T1235 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 531190 T1235 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 531190 T1235 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 531203 T1235 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 531215 T1235 oass.SolrIndexSearcher.<init> Opening Searcher@8d808f main
[junit4:junit4] 2> 531218 T1235 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 531218 T1235 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 531223 T1236 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@8d808f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 531224 T1235 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 531224 T1235 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53601/s_k collection:control_collection shard:shard1
[junit4:junit4] 2> 531227 T1235 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 531249 T1235 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 531257 T1235 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 531257 T1235 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 531257 T1235 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53601/s_k/collection1/
[junit4:junit4] 2> 531258 T1235 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 531258 T1235 oasc.SyncStrategy.syncToMe http://127.0.0.1:53601/s_k/collection1/ has no replicas
[junit4:junit4] 2> 531258 T1235 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53601/s_k/collection1/
[junit4:junit4] 2> 531258 T1235 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 532751 T1233 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 532786 T1232 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> 532841 T1235 oasc.ZkController.register We are http://127.0.0.1:53601/s_k/collection1/ and leader is http://127.0.0.1:53601/s_k/collection1/
[junit4:junit4] 2> 532841 T1235 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53601/s_k
[junit4:junit4] 2> 532842 T1235 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 532842 T1235 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 532842 T1235 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 532848 T1235 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 532851 T1210 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 532852 T1210 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 532852 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 532869 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 532873 T1210 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 532879 T1239 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1243701 name:ZooKeeperConnection Watcher:127.0.0.1:53594/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 532880 T1210 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 532883 T1210 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 532889 T1210 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 533550 T1210 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 533566 T1210 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53613
[junit4:junit4] 2> 533567 T1210 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 533568 T1210 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 533568 T1210 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty1-1371546357507
[junit4:junit4] 2> 533569 T1210 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty1-1371546357507\solr.xml
[junit4:junit4] 2> 533571 T1210 oasc.CoreContainer.<init> New CoreContainer 15375704
[junit4:junit4] 2> 533571 T1210 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty1-1371546357507\'
[junit4:junit4] 2> 533572 T1210 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty1-1371546357507\'
[junit4:junit4] 2> 533755 T1210 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 533756 T1210 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 533757 T1210 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 533757 T1210 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 533757 T1210 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 533759 T1210 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 533759 T1210 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 533760 T1210 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 533760 T1210 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 533761 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 533778 T1210 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 533778 T1210 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53594/solr
[junit4:junit4] 2> 533779 T1210 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 533782 T1210 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 533804 T1250 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@32339a name:ZooKeeperConnection Watcher:127.0.0.1:53594 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 533805 T1210 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 533811 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 533812 T1212 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f5688770c0005, 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> 533826 T1210 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 533830 T1252 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b9f3e name:ZooKeeperConnection Watcher:127.0.0.1:53594/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 533832 T1210 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 533843 T1210 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 534394 T1233 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 534396 T1233 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:53601_s_k",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53601/s_k"}
[junit4:junit4] 2> 534409 T1239 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> 534410 T1252 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> 534412 T1232 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> 534844 T1210 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53613_s_k
[junit4:junit4] 2> 534847 T1210 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53613_s_k
[junit4:junit4] 2> 534855 T1252 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 534856 T1252 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> 534855 T1239 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 534856 T1239 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> 534856 T1232 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 534857 T1232 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> 534882 T1253 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 534883 T1253 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 535910 T1233 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 535911 T1233 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:53613_s_k",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53613/s_k"}
[junit4:junit4] 2> 535911 T1233 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 1
[junit4:junit4] 2> 535911 T1233 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 535936 T1252 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> 535937 T1232 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> 535937 T1239 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> 536869 T1253 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty1-1371546357507\collection1
[junit4:junit4] 2> 536869 T1253 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 536871 T1253 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 536871 T1253 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 536874 T1253 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty1-1371546357507\collection1\'
[junit4:junit4] 2> 536876 T1253 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1371546357507/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 536876 T1253 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty1-1371546357507/collection1/lib/README' to classloader
[junit4:junit4] 2> 536929 T1253 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 537021 T1253 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 537024 T1253 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 537032 T1253 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 537803 T1253 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 537823 T1253 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 537829 T1253 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 537858 T1253 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 537865 T1253 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 537873 T1253 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 537876 T1253 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 537877 T1253 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 537877 T1253 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 537880 T1253 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 537880 T1253 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 537880 T1253 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 537881 T1253 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty1-1371546357507\collection1\, dataDir=.\org.apache.solr.cloud.SyncSliceTest-1371546351361/jetty1\
[junit4:junit4] 2> 537881 T1253 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2143e4
[junit4:junit4] 2> 537881 T1253 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 537882 T1253 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1
[junit4:junit4] 2> 537883 T1253 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.SyncSliceTest-1371546351361/jetty1\index/
[junit4:junit4] 2> 537884 T1253 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 537884 T1253 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index
[junit4:junit4] 2> 537898 T1253 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 537898 T1253 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 537902 T1253 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 537902 T1253 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 537903 T1253 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 537904 T1253 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 537904 T1253 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 537904 T1253 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 537905 T1253 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 537905 T1253 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 537906 T1253 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 537916 T1253 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 537926 T1253 oass.SolrIndexSearcher.<init> Opening Searcher@19c7b65 main
[junit4:junit4] 2> 537928 T1253 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 537928 T1253 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 537935 T1254 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@19c7b65 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 537937 T1253 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 537937 T1253 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53613/s_k collection:collection1 shard:shard1
[junit4:junit4] 2> 537939 T1253 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 538033 T1253 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 538042 T1253 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 538042 T1253 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 538042 T1253 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53613/s_k/collection1/
[junit4:junit4] 2> 538042 T1253 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 538042 T1253 oasc.SyncStrategy.syncToMe http://127.0.0.1:53613/s_k/collection1/ has no replicas
[junit4:junit4] 2> 538042 T1253 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53613/s_k/collection1/
[junit4:junit4] 2> 538043 T1253 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 538924 T1233 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 538954 T1252 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> 538954 T1232 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> 538955 T1239 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> 538963 T1253 oasc.ZkController.register We are http://127.0.0.1:53613/s_k/collection1/ and leader is http://127.0.0.1:53613/s_k/collection1/
[junit4:junit4] 2> 538963 T1253 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53613/s_k
[junit4:junit4] 2> 538963 T1253 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 538964 T1253 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 538965 T1253 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 538973 T1253 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 538976 T1210 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 538977 T1210 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 538988 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 539519 T1210 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 539526 T1210 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53622
[junit4:junit4] 2> 539528 T1210 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 539528 T1210 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 539529 T1210 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty2-1371546363613
[junit4:junit4] 2> 539529 T1210 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty2-1371546363613\solr.xml
[junit4:junit4] 2> 539530 T1210 oasc.CoreContainer.<init> New CoreContainer 12952954
[junit4:junit4] 2> 539530 T1210 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty2-1371546363613\'
[junit4:junit4] 2> 539531 T1210 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty2-1371546363613\'
[junit4:junit4] 2> 539699 T1210 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 539700 T1210 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 539701 T1210 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 539701 T1210 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 539701 T1210 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 539702 T1210 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 539702 T1210 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 539703 T1210 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 539703 T1210 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 539704 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 539719 T1210 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 539719 T1210 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53594/solr
[junit4:junit4] 2> 539721 T1210 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 539723 T1210 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 539740 T1266 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f299df name:ZooKeeperConnection Watcher:127.0.0.1:53594 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 539741 T1210 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 539747 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 539755 T1210 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 539760 T1268 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@e322bb name:ZooKeeperConnection Watcher:127.0.0.1:53594/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 539760 T1210 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 539770 T1210 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 540463 T1233 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 540465 T1233 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:53613_s_k",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53613/s_k"}
[junit4:junit4] 2> 540480 T1239 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> 540480 T1252 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> 540481 T1268 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> 540482 T1232 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> 540765 T1210 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53622_s_k
[junit4:junit4] 2> 540768 T1210 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53622_s_k
[junit4:junit4] 2> 540776 T1239 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 540776 T1239 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> 540777 T1252 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 540777 T1252 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> 540778 T1268 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 540778 T1268 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> 540779 T1232 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 540780 T1232 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> 540794 T1269 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 540794 T1269 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 541990 T1233 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 541990 T1233 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:53622_s_k",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53622/s_k"}
[junit4:junit4] 2> 541990 T1233 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 541990 T1233 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 542003 T1239 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> 542004 T1252 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> 542004 T1232 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> 542005 T1268 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> 542776 T1269 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty2-1371546363613\collection1
[junit4:junit4] 2> 542776 T1269 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 542777 T1269 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 542777 T1269 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 542781 T1269 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty2-1371546363613\collection1\'
[junit4:junit4] 2> 542783 T1269 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1371546363613/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 542783 T1269 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty2-1371546363613/collection1/lib/README' to classloader
[junit4:junit4] 2> 542845 T1269 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 542915 T1269 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 542919 T1269 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 542923 T1269 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 543809 T1269 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 543824 T1269 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 543830 T1269 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 543856 T1269 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 543863 T1269 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 543871 T1269 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 543872 T1269 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 543872 T1269 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 543873 T1269 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 543875 T1269 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 543876 T1269 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 543876 T1269 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 543876 T1269 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty2-1371546363613\collection1\, dataDir=.\org.apache.solr.cloud.SyncSliceTest-1371546351361/jetty2\
[junit4:junit4] 2> 543876 T1269 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2143e4
[junit4:junit4] 2> 543877 T1269 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 543878 T1269 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2
[junit4:junit4] 2> 543879 T1269 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.SyncSliceTest-1371546351361/jetty2\index/
[junit4:junit4] 2> 543881 T1269 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 543881 T1269 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2\index
[junit4:junit4] 2> 543895 T1269 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@16674e4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 543895 T1269 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 543900 T1269 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 543900 T1269 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 543902 T1269 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 543903 T1269 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 543904 T1269 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 543904 T1269 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 543904 T1269 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 543904 T1269 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 543905 T1269 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 543920 T1269 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 543935 T1269 oass.SolrIndexSearcher.<init> Opening Searcher@1857f06 main
[junit4:junit4] 2> 543938 T1269 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 543938 T1269 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 543944 T1270 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1857f06 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 543947 T1269 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 543948 T1269 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53622/s_k collection:collection1 shard:shard1
[junit4:junit4] 2> 543956 T1269 oasc.ZkController.register We are http://127.0.0.1:53622/s_k/collection1/ and leader is http://127.0.0.1:53613/s_k/collection1/
[junit4:junit4] 2> 543956 T1269 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53622/s_k
[junit4:junit4] 2> 543956 T1269 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 543957 T1269 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2603 name=collection1 org.apache.solr.core.SolrCore@1dffda9 url=http://127.0.0.1:53622/s_k/collection1 node=127.0.0.1:53622_s_k C2603_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:53622_s_k, base_url=http://127.0.0.1:53622/s_k}
[junit4:junit4] 2> 543958 T1271 C2603 P53622 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 543958 T1271 C2603 P53622 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 543959 T1271 C2603 P53622 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 543959 T1271 C2603 P53622 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 543959 T1269 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 543963 T1271 C2603 P53622 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 543966 T1210 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 543966 T1210 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 543967 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 543979 T1246 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 544394 T1210 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 544400 T1210 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53632
[junit4:junit4] 2> 544401 T1210 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 544402 T1210 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 544402 T1210 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty3-1371546368593
[junit4:junit4] 2> 544403 T1210 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty3-1371546368593\solr.xml
[junit4:junit4] 2> 544403 T1210 oasc.CoreContainer.<init> New CoreContainer 28872346
[junit4:junit4] 2> 544404 T1210 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty3-1371546368593\'
[junit4:junit4] 2> 544404 T1210 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty3-1371546368593\'
[junit4:junit4] 2> 544556 T1210 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 544556 T1210 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 544557 T1210 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 544557 T1210 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 544558 T1210 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 544559 T1210 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 544559 T1210 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 544559 T1210 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 544560 T1210 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 544560 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 544572 T1210 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 544573 T1210 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53594/solr
[junit4:junit4] 2> 544573 T1210 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 544576 T1210 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 544592 T1283 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1ee441 name:ZooKeeperConnection Watcher:127.0.0.1:53594 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 544594 T1210 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 544599 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 544610 T1210 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 544615 T1285 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2e6e25 name:ZooKeeperConnection Watcher:127.0.0.1:53594/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 544615 T1210 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 544626 T1210 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 544867 T1233 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 544868 T1233 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:53622_s_k",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53622/s_k"}
[junit4:junit4] 2> 544883 T1285 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> 544884 T1239 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> 544885 T1268 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> 544885 T1252 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> 544885 T1232 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> 545524 T1210 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53632_s_k
[junit4:junit4] 2> 545526 T1210 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53632_s_k
[junit4:junit4] 2> 545531 T1285 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> 545532 T1252 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 545532 T1252 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> 545533 T1232 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 545534 T1239 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 545534 T1239 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> 545534 T1268 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 545536 T1268 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> 545534 T1232 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> 545538 T1285 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 545551 T1286 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 545551 T1286 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 545762 T1246 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 3, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 545762 T1246 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=3&state=recovering&nodeName=127.0.0.1:53622_s_k&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1783
[junit4:junit4] 2> 546238 T1233 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 546240 T1233 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:53632_s_k",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53632/s_k"}
[junit4:junit4] 2> 546240 T1233 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 546240 T1233 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 546254 T1285 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> 546255 T1232 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> 546255 T1268 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> 546255 T1239 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> 546255 T1252 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> 546444 T1286 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty3-1371546368593\collection1
[junit4:junit4] 2> 546444 T1286 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 546445 T1286 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 546446 T1286 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 546449 T1286 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty3-1371546368593\collection1\'
[junit4:junit4] 2> 546450 T1286 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1371546368593/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 546450 T1286 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty3-1371546368593/collection1/lib/README' to classloader
[junit4:junit4] 2> 546506 T1286 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 546566 T1286 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 546577 T1286 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 546584 T1286 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 547263 T1286 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 547280 T1286 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 547284 T1286 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 547316 T1286 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 547321 T1286 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 547327 T1286 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 547329 T1286 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 547330 T1286 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 547330 T1286 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 547332 T1286 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 547332 T1286 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 547332 T1286 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 547333 T1286 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty3-1371546368593\collection1\, dataDir=.\org.apache.solr.cloud.SyncSliceTest-1371546351361/jetty3\
[junit4:junit4] 2> 547333 T1286 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2143e4
[junit4:junit4] 2> 547333 T1286 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 547334 T1286 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3
[junit4:junit4] 2> 547334 T1286 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.SyncSliceTest-1371546351361/jetty3\index/
[junit4:junit4] 2> 547335 T1286 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 547335 T1286 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3\index
[junit4:junit4] 2> 547347 T1286 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4eb32f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 547347 T1286 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 547351 T1286 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 547351 T1286 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 547352 T1286 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 547353 T1286 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 547353 T1286 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 547353 T1286 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 547354 T1286 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 547354 T1286 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 547354 T1286 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 547365 T1286 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 547374 T1286 oass.SolrIndexSearcher.<init> Opening Searcher@1b8dbeb main
[junit4:junit4] 2> 547375 T1286 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 547375 T1286 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 547380 T1287 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b8dbeb main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 547381 T1286 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 547381 T1286 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53632/s_k collection:collection1 shard:shard1
[junit4:junit4] 2> 547387 T1286 oasc.ZkController.register We are http://127.0.0.1:53632/s_k/collection1/ and leader is http://127.0.0.1:53613/s_k/collection1/
[junit4:junit4] 2> 547387 T1286 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53632/s_k
[junit4:junit4] 2> 547387 T1286 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 547387 T1286 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2604 name=collection1 org.apache.solr.core.SolrCore@1cbfd8e url=http://127.0.0.1:53632/s_k/collection1 node=127.0.0.1:53632_s_k C2604_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:53632_s_k, base_url=http://127.0.0.1:53632/s_k}
[junit4:junit4] 2> 547388 T1288 C2604 P53632 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 547389 T1286 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 547389 T1288 C2604 P53632 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 547390 T1288 C2604 P53632 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 547390 T1288 C2604 P53632 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 547392 T1210 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 547393 T1210 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 547394 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 547394 T1288 C2604 P53632 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 547407 T1243 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> ASYNC NEW_CORE C2605 name=collection1 org.apache.solr.core.SolrCore@1dffda9 url=http://127.0.0.1:53622/s_k/collection1 node=127.0.0.1:53622_s_k C2605_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:53622_s_k, base_url=http://127.0.0.1:53622/s_k}
[junit4:junit4] 2> 547546 T1271 C2605 P53622 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:53613/s_k/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 547546 T1271 C2605 P53622 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53622/s_k START replicas=[http://127.0.0.1:53613/s_k/collection1/] nUpdates=100
[junit4:junit4] 2> 547549 T1271 C2605 P53622 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 547549 T1271 C2605 P53622 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 547549 T1271 C2605 P53622 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 547549 T1271 C2605 P53622 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 547550 T1271 C2605 P53622 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 547550 T1271 C2605 P53622 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:53613/s_k/collection1/. core=collection1
[junit4:junit4] 2> 547551 T1271 C2605 P53622 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2606 name=collection1 org.apache.solr.core.SolrCore@12c3f84 url=http://127.0.0.1:53613/s_k/collection1 node=127.0.0.1:53613_s_k C2606_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53613_s_k, base_url=http://127.0.0.1:53613/s_k, leader=true}
[junit4:junit4] 2> 547595 T1248 C2606 P53613 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 547596 T1246 C2606 P53613 oasc.SolrCore.execute [collection1] webapp=/s_k path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 547602 T1248 C2606 P53613 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 547602 T1248 C2606 P53613 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 547610 T1233 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 547611 T1233 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:53632_s_k",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53632/s_k"}
[junit4:junit4] 2> 547618 T1248 C2606 P53613 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 547618 T1248 C2606 P53613 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 547622 T1248 C2606 P53613 oass.SolrIndexSearcher.<init> Opening Searcher@794e41 realtime
[junit4:junit4] 2> 547622 T1248 C2606 P53613 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 547622 T1248 C2606 P53613 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 28
[junit4:junit4] 2> 547623 T1271 C2605 P53622 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 547624 T1271 C2605 P53622 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 547628 T1245 C2606 P53613 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 547628 T1245 C2606 P53613 oasc.SolrCore.execute [collection1] webapp=/s_k path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 547629 T1271 C2605 P53622 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 547629 T1271 C2605 P53622 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 547629 T1271 C2605 P53622 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 547635 T1247 C2606 P53613 oasc.SolrCore.execute [collection1] webapp=/s_k path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=3
[junit4:junit4] 2> 547635 T1271 C2605 P53622 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 547638 T1271 C2605 P53622 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2\index.20130618050612252
[junit4:junit4] 2> 547641 T1271 C2605 P53622 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2\index.20130618050612252 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ef8b10; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 547645 T1246 C2606 P53613 oasc.SolrCore.execute [collection1] webapp=/s_k path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 547648 T1271 C2605 P53622 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 547658 T1271 C2605 P53622 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 547658 T1271 C2605 P53622 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 547666 T1271 C2605 P53622 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@16674e4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@16674e4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 547667 T1285 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> 547667 T1239 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> 547667 T1271 C2605 P53622 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 547668 T1271 C2605 P53622 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 547669 T1252 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> 547670 T1271 C2605 P53622 oass.SolrIndexSearcher.<init> Opening Searcher@f9d6cc main
[junit4:junit4] 2> 547675 T1270 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@f9d6cc main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 547677 T1271 C2605 P53622 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2\index.20130618050612252 [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2\index.20130618050612252;done=true>>]
[junit4:junit4] 2> 547677 T1271 C2605 P53622 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2\index.20130618050612252
[junit4:junit4] 2> 547677 T1271 C2605 P53622 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2\index.20130618050612252
[junit4:junit4] 2> 547679 T1232 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> 547680 T1271 C2605 P53622 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 547680 T1271 C2605 P53622 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 547680 T1271 C2605 P53622 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 547681 T1271 C2605 P53622 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 547680 T1268 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> 547689 T1271 C2605 P53622 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 547768 T1210 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 547772 T1210 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53645
[junit4:junit4] 2> 547773 T1210 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 547774 T1210 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 547774 T1210 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty4-1371546372023
[junit4:junit4] 2> 547775 T1210 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty4-1371546372023\solr.xml
[junit4:junit4] 2> 547776 T1210 oasc.CoreContainer.<init> New CoreContainer 10170464
[junit4:junit4] 2> 547776 T1210 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty4-1371546372023\'
[junit4:junit4] 2> 547776 T1210 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty4-1371546372023\'
[junit4:junit4] 2> 547906 T1210 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 547906 T1210 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 547906 T1210 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 547906 T1210 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 547906 T1210 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 547907 T1210 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 547908 T1210 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 547908 T1210 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 547908 T1210 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 547908 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 547920 T1210 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 547921 T1210 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53594/solr
[junit4:junit4] 2> 547922 T1210 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 547923 T1210 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 547935 T1302 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13dcdf4 name:ZooKeeperConnection Watcher:127.0.0.1:53594 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 547936 T1210 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 547941 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 547941 T1212 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f5688770c000b, 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> 547952 T1210 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 547957 T1304 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@145803e name:ZooKeeperConnection Watcher:127.0.0.1:53594/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 547957 T1210 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 547969 T1210 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 548298 T1243 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 548298 T1243 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:53632_s_k&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=891
[junit4:junit4] 2> 548867 T1210 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53645_s_k
[junit4:junit4] 2> 548874 T1210 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53645_s_k
[junit4:junit4] 2> 548878 T1285 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> 548881 T1239 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 548881 T1239 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> 548882 T1304 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 548883 T1252 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 548884 T1252 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> 548884 T1232 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 548885 T1232 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> 548886 T1268 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 548886 T1268 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> 548887 T1285 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 548900 T1305 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 548900 T1305 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 549038 T1233 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 549039 T1233 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:53622_s_k",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53622/s_k"}
[junit4:junit4] 2> 549049 T1233 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:53645_s_k",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53645/s_k"}
[junit4:junit4] 2> 549050 T1233 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=1
[junit4:junit4] 2> 549050 T1233 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 549061 T1285 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> 549062 T1239 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> 549062 T1304 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> 549063 T1252 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> 549063 T1232 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> 549063 T1268 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> 549793 T1305 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty4-1371546372023\collection1
[junit4:junit4] 2> 549793 T1305 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 549795 T1305 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 549795 T1305 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 549797 T1305 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty4-1371546372023\collection1\'
[junit4:junit4] 2> 549799 T1305 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1371546372023/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 549800 T1305 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.SyncSliceTest-jetty4-1371546372023/collection1/lib/README' to classloader
[junit4:junit4] 2> 549883 T1305 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 549972 T1305 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 549974 T1305 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 549982 T1305 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C2607 name=collection1 org.apache.solr.core.SolrCore@1cbfd8e url=http://127.0.0.1:53632/s_k/collection1 node=127.0.0.1:53632_s_k C2607_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:53632_s_k, base_url=http://127.0.0.1:53632/s_k}
[junit4:junit4] 2> 550081 T1288 C2607 P53632 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:53613/s_k/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 550081 T1288 C2607 P53632 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53632/s_k START replicas=[http://127.0.0.1:53613/s_k/collection1/] nUpdates=100
[junit4:junit4] 2> 550082 T1288 C2607 P53632 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 550083 T1288 C2607 P53632 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 550083 T1288 C2607 P53632 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 550084 T1288 C2607 P53632 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 550084 T1288 C2607 P53632 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 550084 T1288 C2607 P53632 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:53613/s_k/collection1/. core=collection1
[junit4:junit4] 2> 550084 T1288 C2607 P53632 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2608 name=collection1 org.apache.solr.core.SolrCore@12c3f84 url=http://127.0.0.1:53613/s_k/collection1 node=127.0.0.1:53613_s_k C2608_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53613_s_k, base_url=http://127.0.0.1:53613/s_k, leader=true}
[junit4:junit4] 2> 550090 T1248 C2608 P53613 oasc.SolrCore.execute [collection1] webapp=/s_k path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 550093 T1248 C2608 P53613 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 550101 T1248 C2608 P53613 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 550101 T1248 C2608 P53613 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 550105 T1248 C2608 P53613 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 550105 T1248 C2608 P53613 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 12
[junit4:junit4] 2> 550107 T1288 C2607 P53632 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 550107 T1288 C2607 P53632 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 550109 T1245 C2608 P53613 oasc.SolrCore.execute [collection1] webapp=/s_k path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 550110 T1288 C2607 P53632 oash.SnapPuller.fetchLatestIndex Master's generation: 3
[junit4:junit4] 2> 550110 T1288 C2607 P53632 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 550110 T1288 C2607 P53632 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 550115 T1247 C2608 P53613 oasc.SolrCore.execute [collection1] webapp=/s_k path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=3&version=2} status=0 QTime=1
[junit4:junit4] 2> 550115 T1288 C2607 P53632 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 550117 T1288 C2607 P53632 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3\index.20130618050614732
[junit4:junit4] 2> 550120 T1288 C2607 P53632 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3\index.20130618050614732 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16697fd; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 550125 T1246 C2608 P53613 oasc.SolrCore.execute [collection1] webapp=/s_k path=/replication params={file=segments_3&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=3} status=0 QTime=0
[junit4:junit4] 2> 550127 T1288 C2607 P53632 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 550132 T1288 C2607 P53632 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 550133 T1288 C2607 P53632 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 550140 T1288 C2607 P53632 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4eb32f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4eb32f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 550140 T1288 C2607 P53632 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 550140 T1288 C2607 P53632 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 550145 T1288 C2607 P53632 oass.SolrIndexSearcher.<init> Opening Searcher@1375522 main
[junit4:junit4] 2> 550146 T1287 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1375522 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 550147 T1288 C2607 P53632 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3\index.20130618050614732 [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3\index.20130618050614732;done=true>>]
[junit4:junit4] 2> 550147 T1288 C2607 P53632 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3\index.20130618050614732
[junit4:junit4] 2> 550147 T1288 C2607 P53632 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3\index.20130618050614732
[junit4:junit4] 2> 550148 T1288 C2607 P53632 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 550150 T1288 C2607 P53632 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 550151 T1288 C2607 P53632 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 550151 T1288 C2607 P53632 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> ASYNC NEW_CORE C2609 name=collection1 org.apache.solr.core.SolrCore@1cbfd8e url=http://127.0.0.1:53632/s_k/collection1 node=127.0.0.1:53632_s_k C2609_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:53632_s_k, base_url=http://127.0.0.1:53632/s_k}
[junit4:junit4] 2> 550193 T1288 C2609 P53632 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 550418 T1233 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 550420 T1233 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:53632_s_k",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53632/s_k"}
[junit4:junit4] 2> 550432 T1252 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> 550433 T1304 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> 550434 T1232 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> 550434 T1285 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> 550434 T1268 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> 550435 T1239 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> 550728 T1305 oass.OpenExchangeRatesOrgProvider.init Initialized with rates=open-exchange-rates.json, refreshInterval=1440.
[junit4:junit4] 2> 550739 T1305 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 550743 T1305 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 550766 T1305 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 550779 T1305 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 550785 T1305 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 550788 T1305 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 550788 T1305 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 550788 T1305 oass.OpenExchangeRatesOrgProvider.reload Reloading exchange rates from open-exchange-rates.json
[junit4:junit4] 2> 550790 T1305 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Unknown key IMPORTANT NOTE
[junit4:junit4] 2> 550790 T1305 oass.OpenExchangeRatesOrgProvider$OpenExchangeRates.<init> WARN Expected key, got STRING
[junit4:junit4] 2> 550790 T1305 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 550791 T1305 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.SyncSliceTest-jetty4-1371546372023\collection1\, dataDir=.\org.apache.solr.cloud.SyncSliceTest-1371546351361/jetty4\
[junit4:junit4] 2> 550791 T1305 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@2143e4
[junit4:junit4] 2> 550791 T1305 oasc.SolrCore.initDirectoryFactory solr.NRTCachingDirectoryFactory
[junit4:junit4] 2> 550792 T1305 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4
[junit4:junit4] 2> 550793 T1305 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.SyncSliceTest-1371546351361/jetty4\index/
[junit4:junit4] 2> 550794 T1305 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 550795 T1305 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4\index
[junit4:junit4] 2> 550804 T1305 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ad3acb; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 550804 T1305 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 550809 T1305 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 550809 T1305 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 550810 T1305 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 550810 T1305 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 550811 T1305 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 550811 T1305 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 550818 T1305 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 550819 T1305 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 550820 T1305 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 550830 T1305 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 550839 T1305 oass.SolrIndexSearcher.<init> Opening Searcher@d10c60 main
[junit4:junit4] 2> 550842 T1305 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 550842 T1305 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 550847 T1308 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d10c60 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 550849 T1305 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 550849 T1305 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53645/s_k collection:collection1 shard:shard1
[junit4:junit4] 2> 550857 T1305 oasc.ZkController.register We are http://127.0.0.1:53645/s_k/collection1/ and leader is http://127.0.0.1:53613/s_k/collection1/
[junit4:junit4] 2> 550857 T1305 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53645/s_k
[junit4:junit4] 2> 550857 T1305 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 550857 T1305 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2610 name=collection1 org.apache.solr.core.SolrCore@5e3229 url=http://127.0.0.1:53645/s_k/collection1 node=127.0.0.1:53645_s_k C2610_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:53645_s_k, base_url=http://127.0.0.1:53645/s_k}
[junit4:junit4] 2> 550857 T1309 C2610 P53645 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 550858 T1309 C2610 P53645 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 550858 T1309 C2610 P53645 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 550858 T1309 C2610 P53645 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 550858 T1305 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 550861 T1309 C2610 P53645 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 550864 T1210 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 550864 T1210 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 550865 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 550877 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 550878 T1248 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 550879 T1210 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 550879 T1210 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 550881 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 551775 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 551783 T1233 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 551784 T1233 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:53645_s_k",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53645/s_k"}
[junit4:junit4] 2> 551793 T1285 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> 551794 T1239 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> 551794 T1252 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> 551795 T1304 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> 551795 T1232 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> 551795 T1268 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> 552660 T1248 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 552660 T1248 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:53645_s_k&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1783
[junit4:junit4] 2> 552667 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 553649 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C2610_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:53645_s_k, base_url=http://127.0.0.1:53645/s_k}
[junit4:junit4] 2> 554619 T1309 C2610 P53645 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:53613/s_k/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 554619 T1309 C2610 P53645 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53645/s_k START replicas=[http://127.0.0.1:53613/s_k/collection1/] nUpdates=100
[junit4:junit4] 2> 554620 T1309 C2610 P53645 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 554620 T1309 C2610 P53645 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 554620 T1309 C2610 P53645 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 554620 T1309 C2610 P53645 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 554620 T1309 C2610 P53645 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 554620 T1309 C2610 P53645 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:53613/s_k/collection1/. core=collection1
[junit4:junit4] 2> 554620 T1309 C2610 P53645 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2611 name=collection1 org.apache.solr.core.SolrCore@12c3f84 url=http://127.0.0.1:53613/s_k/collection1 node=127.0.0.1:53613_s_k C2611_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53613_s_k, base_url=http://127.0.0.1:53613/s_k, leader=true}
[junit4:junit4] 2> 554622 T1245 C2611 P53613 oasc.SolrCore.execute [collection1] webapp=/s_k path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 554628 T1248 C2611 P53613 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 554631 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 554644 T1248 C2611 P53613 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=3
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 554645 T1248 C2611 P53613 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 554647 T1248 C2611 P53613 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 554647 T1248 C2611 P53613 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 19
[junit4:junit4] 2> 554649 T1309 C2610 P53645 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 554649 T1309 C2610 P53645 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 554651 T1246 C2611 P53613 oasc.SolrCore.execute [collection1] webapp=/s_k path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 554652 T1309 C2610 P53645 oash.SnapPuller.fetchLatestIndex Master's generation: 4
[junit4:junit4] 2> 554652 T1309 C2610 P53645 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 554652 T1309 C2610 P53645 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 554658 T1243 C2611 P53613 oasc.SolrCore.execute [collection1] webapp=/s_k path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=4&version=2} status=0 QTime=3
[junit4:junit4] 2> 554659 T1309 C2610 P53645 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 554661 T1309 C2610 P53645 oasc.CachingDirectoryFactory.get return new directory for C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4\index.20130618050619275
[junit4:junit4] 2> 554663 T1309 C2610 P53645 oash.SnapPuller.fetchLatestIndex Starting download to NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4\index.20130618050619275 lockFactory=org.apache.lucene.store.NativeFSLockFactory@bd5c81; maxCacheMB=48.0 maxMergeSizeMB=4.0) fullCopy=false
[junit4:junit4] 2> 554666 T1244 C2611 P53613 oasc.SolrCore.execute [collection1] webapp=/s_k path=/replication params={file=segments_4&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=4} status=0 QTime=0
[junit4:junit4] 2> ASYNC NEW_CORE C2612 name=collection1 org.apache.solr.core.SolrCore@5e3229 url=http://127.0.0.1:53645/s_k/collection1 node=127.0.0.1:53645_s_k C2612_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:53645_s_k, base_url=http://127.0.0.1:53645/s_k}
[junit4:junit4] 2> 554675 T1309 C2612 P53645 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 554681 T1309 C2612 P53645 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 554681 T1309 C2612 P53645 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 554685 T1309 C2612 P53645 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ad3acb; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ad3acb; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 554687 T1309 C2612 P53645 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 554687 T1309 C2612 P53645 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 554689 T1309 C2612 P53645 oass.SolrIndexSearcher.<init> Opening Searcher@196f998 main
[junit4:junit4] 2> 554690 T1308 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@196f998 main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 554691 T1309 C2612 P53645 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4\index.20130618050619275 [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4\index.20130618050619275;done=true>>]
[junit4:junit4] 2> 554691 T1309 C2612 P53645 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4\index.20130618050619275
[junit4:junit4] 2> 554691 T1309 C2612 P53645 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4\index.20130618050619275
[junit4:junit4] 2> 554692 T1309 C2612 P53645 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 554693 T1309 C2612 P53645 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 554693 T1309 C2612 P53645 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 554693 T1309 C2612 P53645 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 554697 T1309 C2612 P53645 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 555614 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 556134 T1233 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 556135 T1233 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:53645_s_k",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53645/s_k"}
[junit4:junit4] 2> 556151 T1285 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> 556152 T1304 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> 556152 T1252 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> 556153 T1232 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> 556152 T1239 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> 556153 T1268 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> 556597 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 556599 T1210 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C2613 name=collection1 org.apache.solr.core.SolrCore@71f114 url=http://127.0.0.1:53601/s_k/collection1 node=127.0.0.1:53601_s_k C2613_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:53601_s_k, base_url=http://127.0.0.1:53601/s_k, leader=true}
[junit4:junit4] 2> 556612 T1226 C2613 P53601 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 556620 T1226 C2613 P53601 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1688f5c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 556621 T1226 C2613 P53601 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 556629 T1226 C2613 P53601 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1688f5c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1688f5c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 556630 T1226 C2613 P53601 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 556634 T1226 C2613 P53601 oass.SolrIndexSearcher.<init> Opening Searcher@1db5c04 main
[junit4:junit4] 2> 556635 T1226 C2613 P53601 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 556635 T1236 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1db5c04 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 556637 T1226 C2613 P53601 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 25
[junit4:junit4] 2> ASYNC NEW_CORE C2614 name=collection1 org.apache.solr.core.SolrCore@1cbfd8e url=http://127.0.0.1:53632/s_k/collection1 node=127.0.0.1:53632_s_k C2614_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53632_s_k, base_url=http://127.0.0.1:53632/s_k}
[junit4:junit4] 2> 556666 T1281 C2614 P53632 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:53613/s_k/collection1/, StdNode: http://127.0.0.1:53622/s_k/collection1/, StdNode: http://127.0.0.1:53632/s_k/collection1/, StdNode: http://127.0.0.1:53645/s_k/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> ASYNC NEW_CORE C2615 name=collection1 org.apache.solr.core.SolrCore@12c3f84 url=http://127.0.0.1:53613/s_k/collection1 node=127.0.0.1:53613_s_k C2615_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53613_s_k, base_url=http://127.0.0.1:53613/s_k, leader=true}
[junit4:junit4] 2> 556673 T1246 C2615 P53613 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 556676 T1276 C2614 P53632 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C2616 name=collection1 org.apache.solr.core.SolrCore@1dffda9 url=http://127.0.0.1:53622/s_k/collection1 node=127.0.0.1:53622_s_k C2616_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53622_s_k, base_url=http://127.0.0.1:53622/s_k}
[junit4:junit4] 2> 556683 T1264 C2616 P53622 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C2612_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53645_s_k, base_url=http://127.0.0.1:53645/s_k}
[junit4:junit4] 2> 556684 T1295 C2612 P53645 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 556696 T1276 C2614 P53632 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4eb32f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4eb32f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 556697 T1295 C2612 P53645 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ad3acb; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ad3acb; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 556698 T1295 C2612 P53645 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 556697 T1276 C2614 P53632 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 556703 T1295 C2612 P53645 oass.SolrIndexSearcher.<init> Opening Searcher@982bad main
[junit4:junit4] 2> 556703 T1295 C2612 P53645 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 556705 T1276 C2614 P53632 oass.SolrIndexSearcher.<init> Opening Searcher@d72080 main
[junit4:junit4] 2> 556705 T1276 C2614 P53632 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 556706 T1287 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@d72080 main{StandardDirectoryReader(segments_3:1:nrt)}
[junit4:junit4] 2> 556706 T1276 C2614 P53632 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 30
[junit4:junit4] 2> 556707 T1308 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@982bad main{StandardDirectoryReader(segments_4:1:nrt)}
[junit4:junit4] 2> 556709 T1295 C2612 P53645 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 26
[junit4:junit4] 2> 556712 T1246 C2615 P53613 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=4
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 556713 T1246 C2615 P53613 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 556715 T1264 C2616 P53622 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@16674e4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@16674e4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 556715 T1264 C2616 P53622 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 556717 T1246 C2615 P53613 oass.SolrIndexSearcher.<init> Opening Searcher@1a93299 main
[junit4:junit4] 2> 556718 T1246 C2615 P53613 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 556719 T1254 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1a93299 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 556720 T1246 C2615 P53613 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 48
[junit4:junit4] 2> 556720 T1264 C2616 P53622 oass.SolrIndexSearcher.<init> Opening Searcher@63ebd8 main
[junit4:junit4] 2> 556721 T1264 C2616 P53622 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 556721 T1270 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@63ebd8 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 556722 T1264 C2616 P53622 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 39
[junit4:junit4] 2> 556723 T1281 C2614 P53632 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 58
[junit4:junit4] 2> 556725 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 556728 T1243 C2615 P53613 oasc.SolrCore.execute [collection1] webapp=/s_k path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 556732 T1259 C2616 P53622 oasc.SolrCore.execute [collection1] webapp=/s_k path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 556734 T1277 C2614 P53632 oasc.SolrCore.execute [collection1] webapp=/s_k path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 556739 T1296 C2612 P53645 oasc.SolrCore.execute [collection1] webapp=/s_k path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 558709 T1224 C2613 P53601 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438170620434055168)} 0 7
[junit4:junit4] 2> 558732 T1264 C2616 P53622 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={update.distrib=FROMLEADER&_version_=-1438170620448735232&update.from=http://127.0.0.1:53613/s_k/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438170620448735232)} 0 2
[junit4:junit4] 2> 558733 T1276 C2614 P53632 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={update.distrib=FROMLEADER&_version_=-1438170620448735232&update.from=http://127.0.0.1:53613/s_k/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438170620448735232)} 0 5
[junit4:junit4] 2> 558738 T1300 C2612 P53645 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={update.distrib=FROMLEADER&_version_=-1438170620448735232&update.from=http://127.0.0.1:53613/s_k/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438170620448735232)} 0 4
[junit4:junit4] 2> 558739 T1247 C2615 P53613 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438170620448735232)} 0 23
[junit4:junit4] 2> 558741 T1263 C2616 P53622 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={wt=javabin&version=2} {deleteByQuery=*:*} 0 30
[junit4:junit4] 2> 558746 T1225 C2613 P53601 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={wt=javabin&version=2} {add=[0 (1438170620477046784)]} 0 4
[junit4:junit4] 2> 558760 T1295 C2612 P53645 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={distrib.from=http://127.0.0.1:53613/s_k/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438170620484386816)]} 0 4
[junit4:junit4] 2> 558763 T1281 C2614 P53632 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={distrib.from=http://127.0.0.1:53613/s_k/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438170620484386816)]} 0 7
[junit4:junit4] 2> 558765 T1259 C2616 P53622 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={distrib.from=http://127.0.0.1:53613/s_k/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438170620484386816)]} 0 7
[junit4:junit4] 2> 558766 T1246 C2615 P53613 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={wt=javabin&version=2} {add=[0 (1438170620484386816)]} 0 17
[junit4:junit4] 2> 558770 T1226 C2613 P53601 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={wt=javabin&version=2} {add=[1 (1438170620505358336)]} 0 1
[junit4:junit4] 2> 558779 T1277 C2614 P53632 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={distrib.from=http://127.0.0.1:53613/s_k/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438170620510601216)]} 0 1
[junit4:junit4] 2> 558779 T1260 C2616 P53622 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={distrib.from=http://127.0.0.1:53613/s_k/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438170620510601216)]} 0 1
[junit4:junit4] 2> 558781 T1296 C2612 P53645 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={distrib.from=http://127.0.0.1:53613/s_k/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438170620510601216)]} 0 1
[junit4:junit4] 2> 558782 T1243 C2615 P53613 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={wt=javabin&version=2} {add=[1 (1438170620510601216)]} 0 8
[junit4:junit4] 2> 558786 T1227 C2613 P53601 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={wt=javabin&version=2} {add=[2 (1438170620522135552)]} 0 0
[junit4:junit4] 2> 558794 T1244 C2615 P53613 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:53622/s_k/collection1/]
[junit4:junit4] 2> 558794 T1244 C2615 P53613 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:53622/s_k/collection1/ against:[http://127.0.0.1:53622/s_k/collection1/] result:true
[junit4:junit4] 2> 558795 T1244 C2615 P53613 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:53632/s_k/collection1/ against:[http://127.0.0.1:53622/s_k/collection1/] result:false
[junit4:junit4] 2> 558795 T1244 C2615 P53613 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:53645/s_k/collection1/ against:[http://127.0.0.1:53622/s_k/collection1/] result:false
[junit4:junit4] 2> 558800 T1297 C2612 P53645 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={distrib.from=http://127.0.0.1:53613/s_k/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:53622/s_k/collection1/&wt=javabin&version=2} {add=[2 (1438170620531572736)]} 0 1
[junit4:junit4] 2> 558800 T1279 C2614 P53632 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={distrib.from=http://127.0.0.1:53613/s_k/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:53622/s_k/collection1/&wt=javabin&version=2} {add=[2 (1438170620531572736)]} 0 1
[junit4:junit4] 2> 558802 T1244 C2615 P53613 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={distrib.from=http://127.0.0.1:53632/s_k/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:53622/s_k/collection1/&wt=javabin&version=2} {add=[2 (1438170620531572736)]} 0 9
[junit4:junit4] 2> 558804 T1278 C2614 P53632 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={test.distrib.skip.servers=http://127.0.0.1:53622/s_k/collection1/&wt=javabin&version=2} {add=[2]} 0 14
[junit4:junit4] 2> 558809 T1228 C2613 P53601 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={wt=javabin&version=2} {add=[3 (1438170620545204224)]} 0 1
[junit4:junit4] 2> 558815 T1245 C2615 P53613 oasup.DistributedUpdateProcessor.setupRequest test.distrib.skip.servers was found and contains:[http://127.0.0.1:53622/s_k/collection1/]
[junit4:junit4] 2> 558816 T1245 C2615 P53613 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:53622/s_k/collection1/ against:[http://127.0.0.1:53622/s_k/collection1/] result:true
[junit4:junit4] 2> 558816 T1245 C2615 P53613 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:53632/s_k/collection1/ against:[http://127.0.0.1:53622/s_k/collection1/] result:false
[junit4:junit4] 2> 558816 T1245 C2615 P53613 oasup.DistributedUpdateProcessor.setupRequest check url:http://127.0.0.1:53645/s_k/collection1/ against:[http://127.0.0.1:53622/s_k/collection1/] result:false
[junit4:junit4] 2> 558821 T1298 C2612 P53645 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={distrib.from=http://127.0.0.1:53613/s_k/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:53622/s_k/collection1/&wt=javabin&version=2} {add=[3 (1438170620554641408)]} 0 1
[junit4:junit4] 2> 558821 T1280 C2614 P53632 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={distrib.from=http://127.0.0.1:53613/s_k/collection1/&update.distrib=FROMLEADER&test.distrib.skip.servers=http://127.0.0.1:53622/s_k/collection1/&wt=javabin&version=2} {add=[3 (1438170620554641408)]} 0 1
[junit4:junit4] 2> 558823 T1245 C2615 P53613 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={distrib.from=http://127.0.0.1:53622/s_k/collection1/&update.distrib=TOLEADER&test.distrib.skip.servers=http://127.0.0.1:53622/s_k/collection1/&wt=javabin&version=2} {add=[3 (1438170620554641408)]} 0 9
[junit4:junit4] 2> 558824 T1261 C2616 P53622 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={test.distrib.skip.servers=http://127.0.0.1:53622/s_k/collection1/&test.distrib.skip.servers=http://127.0.0.1:53632/s_k/collection1/&wt=javabin&version=2} {add=[3]} 0 12
[junit4:junit4] 2> 558828 T1223 C2613 P53601 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 558883 T1223 C2613 P53601 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1688f5c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\control\data\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1688f5c; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 558883 T1223 C2613 P53601 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 558890 T1223 C2613 P53601 oass.SolrIndexSearcher.<init> Opening Searcher@8049ac main
[junit4:junit4] 2> 558891 T1223 C2613 P53601 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 558892 T1236 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@8049ac main{StandardDirectoryReader(segments_3:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 558892 T1223 C2613 P53601 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 64
[junit4:junit4] 2> 558895 T1248 C2615 P53613 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:53613/s_k/collection1/, StdNode: http://127.0.0.1:53622/s_k/collection1/, StdNode: http://127.0.0.1:53632/s_k/collection1/, StdNode: http://127.0.0.1:53645/s_k/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 558898 T1276 C2614 P53632 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 558899 T1247 C2615 P53613 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 558898 T1299 C2612 P53645 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 558900 T1262 C2616 P53622 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 558965 T1299 C2612 P53645 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ad3acb; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty4\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@1ad3acb; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 558966 T1299 C2612 P53645 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 558972 T1299 C2612 P53645 oass.SolrIndexSearcher.<init> Opening Searcher@1fad864 main
[junit4:junit4] 2> 558973 T1299 C2612 P53645 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 558973 T1276 C2614 P53632 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4eb32f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty3\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@4eb32f; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> 558974 T1276 C2614 P53632 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 558987 T1308 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1fad864 main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> ASYNC NEW_CORE C2617 name=collection1 org.apache.solr.core.SolrCore@5e3229 url=http://127.0.0.1:53645/s_k/collection1 node=127.0.0.1:53645_s_k C2617_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53645_s_k, base_url=http://127.0.0.1:53645/s_k}
[junit4:junit4] 2> 558988 T1299 C2617 P53645 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 90
[junit4:junit4] 2> ASYNC NEW_CORE C2618 name=collection1 org.apache.solr.core.SolrCore@1cbfd8e url=http://127.0.0.1:53632/s_k/collection1 node=127.0.0.1:53632_s_k C2618_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53632_s_k, base_url=http://127.0.0.1:53632/s_k}
[junit4:junit4] 2> 558998 T1276 C2618 P53632 oass.SolrIndexSearcher.<init> Opening Searcher@998af main
[junit4:junit4] 2> 558999 T1276 C2618 P53632 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 559002 T1287 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@998af main{StandardDirectoryReader(segments_5:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 559003 T1276 C2618 P53632 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 105
[junit4:junit4] 2> ASYNC NEW_CORE C2619 name=collection1 org.apache.solr.core.SolrCore@12c3f84 url=http://127.0.0.1:53613/s_k/collection1 node=127.0.0.1:53613_s_k C2619_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53613_s_k, base_url=http://127.0.0.1:53613/s_k, leader=true}
[junit4:junit4] 2> 559034 T1247 C2619 P53613 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=5
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_5,generation=5}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty1\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@b19d65; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_6,generation=6}
[junit4:junit4] 2> 559037 T1247 C2619 P53613 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 6
[junit4:junit4] 2> 559044 T1247 C2619 P53613 oass.SolrIndexSearcher.<init> Opening Searcher@1c6b6bd main
[junit4:junit4] 2> 559045 T1247 C2619 P53613 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 559046 T1254 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1c6b6bd main{StandardDirectoryReader(segments_6:3:nrt _0(4.4):c4)}
[junit4:junit4] 2> 559047 T1247 C2619 P53613 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 149
[junit4:junit4] 2> ASYNC NEW_CORE C2620 name=collection1 org.apache.solr.core.SolrCore@1dffda9 url=http://127.0.0.1:53622/s_k/collection1 node=127.0.0.1:53622_s_k C2620_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53622_s_k, base_url=http://127.0.0.1:53622/s_k}
[junit4:junit4] 2> 559054 T1262 C2620 P53622 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@16674e4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_3,generation=3}
[junit4:junit4] 2> commit{dir=NRTCachingDirectory(org.apache.lucene.store.SimpleFSDirectory@C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.SyncSliceTest-1371546351361\jetty2\index lockFactory=org.apache.lucene.store.NativeFSLockFactory@16674e4; maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_4,generation=4}
[junit4:junit4] 2> 559055 T1262 C2620 P53622 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 4
[junit4:junit4] 2> 559065 T1262 C2620 P53622 oass.SolrIndexSearcher.<init> Opening Searcher@5ecc3a main
[junit4:junit4] 2> 559066 T1262 C2620 P53622 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 559066 T1270 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5ecc3a main{StandardDirectoryReader(segments_4:3:nrt _0(4.4):c2)}
[junit4:junit4] 2> 559068 T1262 C2620 P53622 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 168
[junit4:junit4] 2> 559068 T1248 C2619 P53613 oasup.LogUpdateProcessor.finish [collection1] webapp=/s_k path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 173
[junit4:junit4] 2> 559069 T1210 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):230
[junit4:junit4] 2> 559070 T1210 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 559072 T1210 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> 559075 T1246 C2619 P53613 oasc.SolrCore.execute [collection1] webapp=/s_k path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> 559078 T1264 C2620 P53622 oasc.SolrCore.execute [collection1] webapp=/s_k path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=2 status=0 QTime=1
[junit4:junit4] 2> 559082 T1281 C2618 P53632 oasc.SolrCore.execute [collection1] webapp=/s_k path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> 559086 T1300 C2617 P53645 oasc.SolrCore.execute [collection1] webapp=/s_k path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=4 status=0 QTime=1
[junit4:junit4] 2> 559087 T1210 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 559100 T1277 oasha.CollectionsHandler.handleSyncShardAction Syncing shard : shard=shard1&action=SYNCSHARD&collection=collection1&wt=javabin&version=2
[junit4:junit4] 2> 559100 T1277 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 559116 T1243 oasha.CoreAdminHandler.handleRequestSyncAction I have been requested to sync up my shard
[junit4:junit4] 2> 559117 T1243 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53613/s_k/collection1/
[junit4:junit4] 2> 559117 T1243 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53613/s_k START replicas=[http://127.0.0.1:53622/s_k/collection1/, http://127.0.0.1:53632/s_k/collection1/, http://127.0.0.1:53645/s_k/collection1/] nUpdates=100
[junit4:junit4] 2> 559131 T1295 C2617 P53645 oasc.SolrCore.execute [collection1] webapp=/s_k path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 559135 T1243 oasu.PeerSync.handleVersions PeerSync: core=collection1 url=http://127.0.0.1:53613/s_k Received 5 versions from 127.0.0.1:53645/s_k/collection1/
[junit4:junit4] 2> 5591
[...truncated too long message...]
kspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371547354664\jetty12
[junit4:junit4] 2> 1692293 T4073 oasc.CachingDirectoryFactory.closeCacheValue looking to close C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371547354664\jetty12\index [CachedDir<<refCount=0;path=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371547354664\jetty12\index;done=false>>]
[junit4:junit4] 2> 1692293 T4073 oasc.CachingDirectoryFactory.close Closing directory: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371547354664\jetty12\index
[junit4:junit4] 2> 1692295 T4586 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89885727436177436-127.0.0.1:55041_-n_0000000012) am no longer a leader.
[junit4:junit4] 2> 1692298 T4313 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 1692311 T4073 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 1692451 T4363 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1692451 T4363 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371547354664\zookeeper\server1\data\version-2\log.1 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371547354664\zookeeper\server1\data\version-2 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371547354664\zookeeper\server1\data FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371547354664\zookeeper\server1 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371547354664\zookeeper FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ChaosMonkeySafeLeaderTest-1371547354664 FAILED !!!!!
[junit4:junit4] 2> 1692749 T4073 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1692753 T4073 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:54902 54902
[junit4:junit4] 2> 1693666 T4313 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1695118 T4313 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 1> safe stop:
[junit4:junit4] 1> safe stop:
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeySafeLeaderTest -Dtests.method=testDistribSearch -Dtests.seed=E5D0D5F06ED66AB1 -Dtests.slow=true -Dtests.locale=tr_TR -Dtests.timezone=Antarctica/Mawson -Dtests.file.encoding=UTF-8
[junit4:junit4] FAILURE 165s | ChaosMonkeySafeLeaderTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: shard3 is not consistent. Got 4 from http://127.0.0.1:55008/collection1lastClient and got 2 from http://127.0.0.1:55041/collection1
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([E5D0D5F06ED66AB1:64365BE819890A8D]:0)
[junit4:junit4] > at org.apache.solr.cloud.AbstractFullDistribZkTestBase.checkShardConsistency(AbstractFullDistribZkTestBase.java:1018)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeySafeLeaderTest.doTest(ChaosMonkeySafeLeaderTest.java:137)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 1695126 T4073 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {range_facet_l=PostingsFormat(name=MockRandom), text=Pulsing41(freqCutoff=12 minBlockSize=18 maxBlockSize=125), _version_=PostingsFormat(name=TestBloomFilteredLucene41Postings), rnd_b=PostingsFormat(name=Memory doPackFST= false), intDefault=PostingsFormat(name=TestBloomFilteredLucene41Postings), timestamp=PostingsFormat(name=MockRandom), id=PostingsFormat(name=Memory doPackFST= false), a_t=PostingsFormat(name=MockRandom), range_facet_sl=PostingsFormat(name=Memory doPackFST= false), range_facet_si=PostingsFormat(name=MockRandom), other_tl1=PostingsFormat(name=TestBloomFilteredLucene41Postings), multiDefault=PostingsFormat(name=MockRandom), a_si=PostingsFormat(name=TestBloomFilteredLucene41Postings)}, docValues:{}, sim=DefaultSimilarity, locale=tr_TR, timezone=Antarctica/Mawson
[junit4:junit4] 2> NOTE: Windows 7 6.1 x86/Oracle Corporation 1.7.0_21 (32-bit)/cpus=2,threads=1,free=32750512,total=190218240
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestRandomFaceting, TestSolrIndexConfig, ShardSplitTest, SolrCmdDistributorTest, TestCSVResponseWriter, DistributedQueryElevationComponentTest, MoreLikeThisHandlerTest, TestCollationField, TestQueryUtils, TestPluginEnable, TestRandomDVFaceting, SolrIndexSplitterTest, TestCollationKeyRangeQueries, DirectSolrConnectionTest, TestZkChroot, DebugComponentTest, TestDistributedGrouping, DisMaxRequestHandlerTest, TestSearchPerf, TestPropInject, DateFieldTest, TestBM25SimilarityFactory, IndexReaderFactoryTest, ZkCLITest, PluginInfoTest, TestNumberUtils, SolrRequestParserTest, TestAnalyzedSuggestions, TestFaceting, DirectUpdateHandlerOptimizeTest, SimpleFacetsTest, SimplePostToolTest, QueryParsingTest, TestManagedSchema, ZkNodePropsTest, TestCSVLoader, TestUtils, SpatialFilterTest, TestJoin, TestWriterPerf, DOMUtilTest, ChaosMonkeyShardSplitTest, ScriptEngineTest, ChaosMonkeyNothingIsSafeTest, CacheHeaderTest, TestDynamicFieldCollectionResource, SolrIndexConfigTest, PolyFieldTest, SyncSliceTest, TestQuerySenderNoQuery, AlternateDirectoryTest, TestPostingsSolrHighlighter, TestSolrDeletionPolicy2, TestSystemIdResolver, BasicDistributedZk2Test, TestRecovery, TestFastOutputStream, TestSolrQueryParserResource, TestSolr4Spatial, TestSort, LukeRequestHandlerTest, TestFieldCollectionResource, TestStressReorder, DocValuesTest, RegexBoostProcessorTest, SpellCheckCollatorTest, TestDocumentBuilder, TestFunctionQuery, TestDFRSimilarityFactory, LeaderElectionTest, QueryElevationComponentTest, PeerSyncTest, FileBasedSpellCheckerTest, OpenCloseCoreStressTest, DefaultValueUpdateProcessorTest, MinimalSchemaTest, TestSolrDeletionPolicy1, TestBinaryResponseWriter, LeaderElectionIntegrationTest, SolrInfoMBeanTest, IndexSchemaRuntimeFieldTest, FastVectorHighlighterTest, TestPHPSerializedResponseWriter, SynonymTokenizerTest, ShowFileRequestHandlerTest, HighlighterTest, MBeansHandlerTest, QueryEqualityTest, HighlighterConfigTest, TestBinaryField, TestPseudoReturnFields, TestLuceneMatchVersion, PreAnalyzedUpdateProcessorTest, FieldMutatingUpdateProcessorTest, DocumentBuilderTest, SuggesterTSTTest, TestLFUCache, TestDefaultSearchFieldResource, TestClassNameShortening, SuggesterWFSTTest, UniqFieldsUpdateProcessorFactoryTest, TestReplicationHandler, TestArbitraryIndexDir, TestSchemaVersionResource, TestQuerySenderListener, TestIndexSearcher, TestReversedWildcardFilterFactory, BasicDistributedZkTest, TestCloudManagedSchemaAddField, TestStressVersions, UpdateRequestProcessorFactoryTest, SolrTestCaseJ4Test, PrimUtilsTest, PingRequestHandlerTest, TestTrie, OverseerCollectionProcessorTest, TestIBSimilarityFactory, TestSurroundQueryParser, SolrCoreCheckLockOnStartupTest, TestPropInjectDefaults, TestSolrXmlPersistence, UnloadDistributedZkTest, SuggesterTest, SearchHandlerTest, TestSolrXml, TestFoldingMultitermQuery, ChaosMonkeySafeLeaderTest]
[junit4:junit4] Completed in 165.11s, 1 test, 1 failure <<< FAILURES!
[...truncated 518 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:392: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:372: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build.xml:181: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\common-build.xml:437: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\lucene\common-build.xml:1246: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\lucene\common-build.xml:890: There were test failures: 298 suites, 1253 tests, 2 failures, 18 ignored (12 assumptions)
Total time: 71 minutes 35 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_21 -server -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure