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/05/23 06:47:55 UTC
[JENKINS] Lucene-Solr-4.x-Windows (32bit/jdk1.6.0_45) - Build #
2817 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Windows/2817/
Java: 32bit/jdk1.6.0_45 -server -XX:+UseConcMarkSweepGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:50174 returned non ok status:500, message:Server Error
Stack Trace:
org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:50174 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([1E54C08CE37E2BE0:9FB24E9494214BDC]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:133)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.GeneratedMethodAccessor40.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
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:662)
Build Log:
[...truncated 9460 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 2676708 T7117 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 2676712 T7117 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-ShardSplitTest-1369284366989
[junit4:junit4] 2> 2676714 T7117 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 2676714 T7118 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 2676801 T7117 oasc.ZkTestServer.run start zk server on port:50155
[junit4:junit4] 2> 2676803 T7117 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2676811 T7124 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@964d64 name:ZooKeeperConnection Watcher:127.0.0.1:50155 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2676812 T7117 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2676812 T7117 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 2676825 T7119 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13ecfb552940000, 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:662)
[junit4:junit4] 2>
[junit4:junit4] 2> 2676826 T7117 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2676834 T7126 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11dac8d name:ZooKeeperConnection Watcher:127.0.0.1:50155/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2676834 T7117 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2676835 T7117 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 2676846 T7117 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 2676855 T7117 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 2676863 T7117 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 2676875 T7117 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> 2676876 T7117 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 2676891 T7117 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 2676892 T7117 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 2676902 T7117 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> 2676903 T7117 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 2676912 T7117 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> 2676913 T7117 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 2676921 T7117 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> 2676922 T7117 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 2676930 T7117 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> 2676931 T7117 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 2676940 T7117 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> 2676941 T7117 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 2676949 T7117 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> 2676951 T7117 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 2676958 T7117 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> 2676960 T7117 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 2676973 T7119 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13ecfb552940001, 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:662)
[junit4:junit4] 2>
[junit4:junit4] 2> 2677367 T7117 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2677369 T7117 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50162
[junit4:junit4] 2> 2677370 T7117 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2677371 T7117 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2677371 T7117 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.ShardSplitTest-controljetty-1369284367248
[junit4:junit4] 2> 2677371 T7117 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.ShardSplitTest-controljetty-1369284367248\solr.xml
[junit4:junit4] 2> 2677372 T7117 oasc.CoreContainer.<init> New CoreContainer 11020025
[junit4:junit4] 2> 2677372 T7117 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.ShardSplitTest-controljetty-1369284367248\'
[junit4:junit4] 2> 2677373 T7117 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.ShardSplitTest-controljetty-1369284367248\'
[junit4:junit4] 2> 2677473 T7117 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2677473 T7117 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2677473 T7117 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2677474 T7117 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2677474 T7117 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2677475 T7117 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2677475 T7117 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2677475 T7117 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2677476 T7117 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2677476 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2677483 T7117 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2677484 T7117 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50155/solr
[junit4:junit4] 2> 2677484 T7117 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2677486 T7117 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2677502 T7137 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1657456 name:ZooKeeperConnection Watcher:127.0.0.1:50155 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2677503 T7117 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2677506 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2677510 T7117 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2677514 T7139 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1490d7b name:ZooKeeperConnection Watcher:127.0.0.1:50155/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2677515 T7117 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2677516 T7117 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 2677523 T7117 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 2677528 T7117 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 2677532 T7117 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50162_
[junit4:junit4] 2> 2677533 T7117 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50162_
[junit4:junit4] 2> 2677537 T7117 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 2677546 T7117 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 2677549 T7117 oasc.Overseer.start Overseer (id=89737420275449859-127.0.0.1:50162_-n_0000000000) starting
[junit4:junit4] 2> 2677555 T7117 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 2677563 T7141 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 2677563 T7117 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 2677567 T7117 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 2677570 T7117 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2677574 T7140 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 2677577 T7142 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.ShardSplitTest-controljetty-1369284367248\collection1
[junit4:junit4] 2> 2677578 T7142 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 2677579 T7142 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2677579 T7142 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 2677581 T7142 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.ShardSplitTest-controljetty-1369284367248\collection1\'
[junit4:junit4] 2> 2677582 T7142 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1369284367248/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2677583 T7142 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1369284367248/collection1/lib/README' to classloader
[junit4:junit4] 2> 2677645 T7142 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2677708 T7142 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2677710 T7142 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2677714 T7142 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2678306 T7142 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2678310 T7142 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2678312 T7142 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2678318 T7142 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2678347 T7142 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2678348 T7142 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.ShardSplitTest-controljetty-1369284367248\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1369284366988/control/data\
[junit4:junit4] 2> 2678348 T7142 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@152643
[junit4:junit4] 2> 2678348 T7142 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2678349 T7142 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369284366988/control/data\
[junit4:junit4] 2> 2678349 T7142 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1369284366988/control/data\index/
[junit4:junit4] 2> 2678349 T7142 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1369284366988\control\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2678349 T7142 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369284366988/control/data\index
[junit4:junit4] 2> 2678354 T7142 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a9515e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1784d1c),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2678354 T7142 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2678356 T7142 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2678357 T7142 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2678357 T7142 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2678358 T7142 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2678358 T7142 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2678358 T7142 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2678360 T7142 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2678360 T7142 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2678360 T7142 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2678367 T7142 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2678373 T7142 oass.SolrIndexSearcher.<init> Opening Searcher@3d87ca main
[junit4:junit4] 2> 2678374 T7142 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1369284366988\control\data\tlog
[junit4:junit4] 2> 2678376 T7142 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2678377 T7142 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2678382 T7143 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3d87ca main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2678383 T7142 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2678383 T7142 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2678878 T7140 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2678880 T7140 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:50162_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50162"}
[junit4:junit4] 2> 2678880 T7140 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2678880 T7140 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 2678897 T7139 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> 2679251 T7142 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2679251 T7142 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50162 collection:control_collection shard:shard1
[junit4:junit4] 2> 2679253 T7142 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2679279 T7142 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2679289 T7142 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2679289 T7142 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2679289 T7142 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50162/collection1/
[junit4:junit4] 2> 2679290 T7142 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2679290 T7142 oasc.SyncStrategy.syncToMe http://127.0.0.1:50162/collection1/ has no replicas
[junit4:junit4] 2> 2679291 T7142 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50162/collection1/
[junit4:junit4] 2> 2679291 T7142 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2680203 T7140 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2680216 T7139 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> 2680238 T7142 oasc.ZkController.register We are http://127.0.0.1:50162/collection1/ and leader is http://127.0.0.1:50162/collection1/
[junit4:junit4] 2> 2680238 T7142 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50162
[junit4:junit4] 2> 2680238 T7142 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2680238 T7142 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2680238 T7142 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2680242 T7142 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2680243 T7117 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2680243 T7117 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2680243 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2680251 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 2680253 T7117 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2680257 T7146 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1bb6bb1 name:ZooKeeperConnection Watcher:127.0.0.1:50155/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2680257 T7117 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2680259 T7117 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2680262 T7117 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 2680634 T7117 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2680637 T7117 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50174
[junit4:junit4] 2> 2680637 T7117 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2680638 T7117 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2680638 T7117 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.ShardSplitTest-jetty1-1369284370538
[junit4:junit4] 2> 2680638 T7117 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.ShardSplitTest-jetty1-1369284370538\solr.xml
[junit4:junit4] 2> 2680639 T7117 oasc.CoreContainer.<init> New CoreContainer 14880284
[junit4:junit4] 2> 2680639 T7117 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.ShardSplitTest-jetty1-1369284370538\'
[junit4:junit4] 2> 2680639 T7117 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.ShardSplitTest-jetty1-1369284370538\'
[junit4:junit4] 2> 2680731 T7117 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2680732 T7117 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2680732 T7117 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2680733 T7117 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2680733 T7117 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2680733 T7117 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2680734 T7117 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2680734 T7117 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2680735 T7117 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2680735 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2680741 T7117 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2680741 T7117 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50155/solr
[junit4:junit4] 2> 2680742 T7117 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2680742 T7117 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2680758 T7157 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7657f1 name:ZooKeeperConnection Watcher:127.0.0.1:50155 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2680759 T7117 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2680761 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2680767 T7117 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2680771 T7159 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@14f71e4 name:ZooKeeperConnection Watcher:127.0.0.1:50155/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2680771 T7117 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2680780 T7117 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2681524 T7140 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2681527 T7140 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:50162_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50162"}
[junit4:junit4] 2> 2681542 T7159 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> 2681543 T7146 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> 2681543 T7139 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> 2681650 T7117 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50174_
[junit4:junit4] 2> 2681655 T7117 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50174_
[junit4:junit4] 2> 2681662 T7139 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> 2681663 T7146 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> 2681664 T7159 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 2681664 T7159 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> 2681669 T7146 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 2681670 T7139 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 2681681 T7160 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.ShardSplitTest-jetty1-1369284370538\collection1
[junit4:junit4] 2> 2681681 T7160 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2681682 T7160 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2681682 T7160 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2681685 T7160 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.ShardSplitTest-jetty1-1369284370538\collection1\'
[junit4:junit4] 2> 2681686 T7160 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1369284370538/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2681687 T7160 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1369284370538/collection1/lib/README' to classloader
[junit4:junit4] 2> 2681752 T7160 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2681822 T7160 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2681824 T7160 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2681829 T7160 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2682434 T7160 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2682438 T7160 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2682440 T7160 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2682445 T7160 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2682473 T7160 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2682473 T7160 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.ShardSplitTest-jetty1-1369284370538\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty1\
[junit4:junit4] 2> 2682474 T7160 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@152643
[junit4:junit4] 2> 2682474 T7160 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2682474 T7160 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty1\
[junit4:junit4] 2> 2682474 T7160 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty1\index/
[junit4:junit4] 2> 2682475 T7160 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1369284366988\jetty1\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2682476 T7160 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty1\index
[junit4:junit4] 2> 2682479 T7160 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@834df4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8e9873),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2682480 T7160 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2682483 T7160 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2682483 T7160 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2682483 T7160 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2682484 T7160 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2682484 T7160 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2682484 T7160 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2682485 T7160 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2682485 T7160 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2682486 T7160 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2682493 T7160 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2682498 T7160 oass.SolrIndexSearcher.<init> Opening Searcher@7d27d1 main
[junit4:junit4] 2> 2682498 T7160 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1369284366988\jetty1\tlog
[junit4:junit4] 2> 2682501 T7160 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2682501 T7160 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2682507 T7161 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7d27d1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2682509 T7160 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2682509 T7160 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2682852 T7140 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2682852 T7140 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[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:50174_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50174"}
[junit4:junit4] 2> 2682853 T7140 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 2682853 T7140 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 2682861 T7159 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> 2682861 T7139 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> 2682861 T7146 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> 2683379 T7160 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2683379 T7160 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50174 collection:collection1 shard:shard1
[junit4:junit4] 2> 2683382 T7160 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 2683408 T7160 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2683418 T7160 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2683418 T7160 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2683418 T7160 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50174/collection1/
[junit4:junit4] 2> 2683420 T7160 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2683420 T7160 oasc.SyncStrategy.syncToMe http://127.0.0.1:50174/collection1/ has no replicas
[junit4:junit4] 2> 2683421 T7160 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50174/collection1/
[junit4:junit4] 2> 2683421 T7160 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 2684148 T7140 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2684165 T7159 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> 2684166 T7146 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> 2684166 T7139 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> 2684175 T7160 oasc.ZkController.register We are http://127.0.0.1:50174/collection1/ and leader is http://127.0.0.1:50174/collection1/
[junit4:junit4] 2> 2684175 T7160 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50174
[junit4:junit4] 2> 2684175 T7160 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2684175 T7160 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2684175 T7160 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2684178 T7160 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2684180 T7117 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2684180 T7117 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2684181 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2684534 T7117 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2684537 T7117 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50183
[junit4:junit4] 2> 2684538 T7117 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2684538 T7117 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2684538 T7117 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.ShardSplitTest-jetty2-1369284374463
[junit4:junit4] 2> 2684538 T7117 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.ShardSplitTest-jetty2-1369284374463\solr.xml
[junit4:junit4] 2> 2684539 T7117 oasc.CoreContainer.<init> New CoreContainer 2714476
[junit4:junit4] 2> 2684539 T7117 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.ShardSplitTest-jetty2-1369284374463\'
[junit4:junit4] 2> 2684539 T7117 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.ShardSplitTest-jetty2-1369284374463\'
[junit4:junit4] 2> 2684630 T7117 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2684631 T7117 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2684631 T7117 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2684632 T7117 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2684632 T7117 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2684632 T7117 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2684633 T7117 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2684633 T7117 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2684633 T7117 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2684634 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2684639 T7117 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2684640 T7117 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50155/solr
[junit4:junit4] 2> 2684640 T7117 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2684641 T7117 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2684653 T7173 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19bea8c name:ZooKeeperConnection Watcher:127.0.0.1:50155 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2684654 T7117 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2684657 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2684664 T7117 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2684667 T7175 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1537e73 name:ZooKeeperConnection Watcher:127.0.0.1:50155/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2684668 T7117 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2684673 T7117 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2685346 T7140 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2685347 T7140 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[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:50174_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50174"}
[junit4:junit4] 2> 2685364 T7146 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> 2685365 T7175 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> 2685366 T7159 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> 2685366 T7139 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> 2685454 T7117 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50183_
[junit4:junit4] 2> 2685460 T7117 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50183_
[junit4:junit4] 2> 2685466 T7175 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> 2685466 T7139 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> 2685467 T7146 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> 2685469 T7159 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2685469 T7159 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> 2685474 T7175 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2685476 T7139 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2685476 T7146 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2685482 T7176 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.ShardSplitTest-jetty2-1369284374463\collection1
[junit4:junit4] 2> 2685482 T7176 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2685483 T7176 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2685483 T7176 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2685485 T7176 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.ShardSplitTest-jetty2-1369284374463\collection1\'
[junit4:junit4] 2> 2685487 T7176 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1369284374463/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2685487 T7176 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1369284374463/collection1/lib/README' to classloader
[junit4:junit4] 2> 2685545 T7176 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2685603 T7176 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2685605 T7176 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2685609 T7176 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2686108 T7176 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2686116 T7176 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2686118 T7176 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2686121 T7176 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2686148 T7176 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2686149 T7176 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.ShardSplitTest-jetty2-1369284374463\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty2\
[junit4:junit4] 2> 2686149 T7176 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@152643
[junit4:junit4] 2> 2686149 T7176 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2686149 T7176 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty2\
[junit4:junit4] 2> 2686150 T7176 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty2\index/
[junit4:junit4] 2> 2686150 T7176 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1369284366988\jetty2\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2686151 T7176 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty2\index
[junit4:junit4] 2> 2686154 T7176 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@deaa83 lockFactory=org.apache.lucene.store.NativeFSLockFactory@973494),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2686155 T7176 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2686157 T7176 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2686157 T7176 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2686158 T7176 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2686159 T7176 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2686159 T7176 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2686159 T7176 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2686159 T7176 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2686160 T7176 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2686160 T7176 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2686167 T7176 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2686173 T7176 oass.SolrIndexSearcher.<init> Opening Searcher@1b3c83b main
[junit4:junit4] 2> 2686174 T7176 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1369284366988\jetty2\tlog
[junit4:junit4] 2> 2686175 T7176 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2686175 T7176 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2686181 T7177 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b3c83b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2686183 T7176 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2686183 T7176 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2686546 T7140 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2686548 T7140 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[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:50183_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50183"}
[junit4:junit4] 2> 2686548 T7140 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 2686548 T7140 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 2686563 T7146 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> 2686564 T7175 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> 2686564 T7159 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> 2686565 T7139 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> 2686966 T7176 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2686966 T7176 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50183 collection:collection1 shard:shard2
[junit4:junit4] 2> 2686968 T7176 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 2686988 T7176 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2686998 T7176 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2686998 T7176 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2686998 T7176 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50183/collection1/
[junit4:junit4] 2> 2686998 T7176 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2686999 T7176 oasc.SyncStrategy.syncToMe http://127.0.0.1:50183/collection1/ has no replicas
[junit4:junit4] 2> 2686999 T7176 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50183/collection1/
[junit4:junit4] 2> 2686999 T7176 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 2687746 T7140 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2687776 T7175 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> 2687776 T7159 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> 2687777 T7139 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> 2687776 T7146 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> 2687806 T7176 oasc.ZkController.register We are http://127.0.0.1:50183/collection1/ and leader is http://127.0.0.1:50183/collection1/
[junit4:junit4] 2> 2687806 T7176 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50183
[junit4:junit4] 2> 2687806 T7176 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2687808 T7176 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2687808 T7176 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2687813 T7176 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2687815 T7117 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2687815 T7117 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2687817 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2688190 T7117 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2688193 T7117 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50192
[junit4:junit4] 2> 2688193 T7117 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2688193 T7117 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2688193 T7117 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.ShardSplitTest-jetty3-1369284378106
[junit4:junit4] 2> 2688194 T7117 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.ShardSplitTest-jetty3-1369284378106\solr.xml
[junit4:junit4] 2> 2688194 T7117 oasc.CoreContainer.<init> New CoreContainer 21916217
[junit4:junit4] 2> 2688195 T7117 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.ShardSplitTest-jetty3-1369284378106\'
[junit4:junit4] 2> 2688196 T7117 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.ShardSplitTest-jetty3-1369284378106\'
[junit4:junit4] 2> 2688288 T7117 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2688289 T7117 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2688289 T7117 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2688289 T7117 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2688289 T7117 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2688289 T7117 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2688289 T7117 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2688290 T7117 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2688290 T7117 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2688290 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2688295 T7117 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2688296 T7117 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50155/solr
[junit4:junit4] 2> 2688296 T7117 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2688298 T7117 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2688312 T7189 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b59bcd name:ZooKeeperConnection Watcher:127.0.0.1:50155 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2688314 T7117 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2688318 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2688329 T7117 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2688334 T7191 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16efa03 name:ZooKeeperConnection Watcher:127.0.0.1:50155/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2688335 T7117 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2688346 T7117 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2688963 T7140 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2688964 T7140 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[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:50183_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50183"}
[junit4:junit4] 2> 2688980 T7146 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> 2688980 T7175 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> 2688982 T7191 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> 2688982 T7139 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> 2688982 T7159 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> 2689132 T7117 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50192_
[junit4:junit4] 2> 2689135 T7117 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50192_
[junit4:junit4] 2> 2689139 T7146 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> 2689140 T7139 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> 2689139 T7175 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> 2689140 T7159 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2689141 T7159 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> 2689141 T7191 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2689141 T7191 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> 2689144 T7146 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2689145 T7139 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2689146 T7175 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2689153 T7192 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.ShardSplitTest-jetty3-1369284378106\collection1
[junit4:junit4] 2> 2689153 T7192 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2689153 T7192 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2689153 T7192 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2689156 T7192 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.ShardSplitTest-jetty3-1369284378106\collection1\'
[junit4:junit4] 2> 2689157 T7192 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1369284378106/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2689159 T7192 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1369284378106/collection1/lib/README' to classloader
[junit4:junit4] 2> 2689213 T7192 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2689271 T7192 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2689273 T7192 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2689277 T7192 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2689791 T7192 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2689795 T7192 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2689796 T7192 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2689800 T7192 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2689826 T7192 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2689826 T7192 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.ShardSplitTest-jetty3-1369284378106\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty3\
[junit4:junit4] 2> 2689826 T7192 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@152643
[junit4:junit4] 2> 2689827 T7192 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2689827 T7192 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty3\
[junit4:junit4] 2> 2689827 T7192 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty3\index/
[junit4:junit4] 2> 2689827 T7192 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1369284366988\jetty3\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2689827 T7192 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty3\index
[junit4:junit4] 2> 2689830 T7192 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2fdcae lockFactory=org.apache.lucene.store.NativeFSLockFactory@1196666),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2689830 T7192 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2689834 T7192 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2689834 T7192 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2689834 T7192 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2689835 T7192 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2689836 T7192 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2689836 T7192 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2689837 T7192 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2689837 T7192 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2689837 T7192 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2689844 T7192 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2689849 T7192 oass.SolrIndexSearcher.<init> Opening Searcher@1d0f93a main
[junit4:junit4] 2> 2689850 T7192 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1369284366988\jetty3\tlog
[junit4:junit4] 2> 2689851 T7192 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2689851 T7192 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2689857 T7193 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d0f93a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2689859 T7192 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2689859 T7192 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2690160 T7140 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2690160 T7140 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[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:50192_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50192"}
[junit4:junit4] 2> 2690160 T7140 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 2690160 T7140 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 2690168 T7146 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> 2690169 T7175 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> 2690169 T7191 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> 2690169 T7159 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> 2690169 T7139 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> 2690642 T7192 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2690642 T7192 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50192 collection:collection1 shard:shard1
[junit4:junit4] 2> 2690648 T7192 oasc.ZkController.register We are http://127.0.0.1:50192/collection1/ and leader is http://127.0.0.1:50174/collection1/
[junit4:junit4] 2> 2690648 T7192 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50192
[junit4:junit4] 2> 2690648 T7192 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 2690648 T7192 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C6884 name=collection1 org.apache.solr.core.SolrCore@78a148 url=http://127.0.0.1:50192/collection1 node=127.0.0.1:50192_ C6884_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:50192_, base_url=http://127.0.0.1:50192}
[junit4:junit4] 2> 2690649 T7194 C6884 P50192 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 2690650 T7194 C6884 P50192 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 2690650 T7194 C6884 P50192 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 2690650 T7194 C6884 P50192 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2690650 T7192 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2690651 T7194 C6884 P50192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2690652 T7117 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2690653 T7117 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2690653 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2690659 T7153 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 2691014 T7117 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2691016 T7117 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50202
[junit4:junit4] 2> 2691017 T7117 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2691017 T7117 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2691017 T7117 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.ShardSplitTest-jetty4-1369284380933
[junit4:junit4] 2> 2691017 T7117 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.ShardSplitTest-jetty4-1369284380933\solr.xml
[junit4:junit4] 2> 2691017 T7117 oasc.CoreContainer.<init> New CoreContainer 563587
[junit4:junit4] 2> 2691018 T7117 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.ShardSplitTest-jetty4-1369284380933\'
[junit4:junit4] 2> 2691018 T7117 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.ShardSplitTest-jetty4-1369284380933\'
[junit4:junit4] 2> 2691106 T7117 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2691106 T7117 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2691106 T7117 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2691107 T7117 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2691107 T7117 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2691107 T7117 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2691108 T7117 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2691108 T7117 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2691108 T7117 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2691109 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2691115 T7117 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2691116 T7117 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50155/solr
[junit4:junit4] 2> 2691116 T7117 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2691118 T7117 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2691133 T7206 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@42f6dd name:ZooKeeperConnection Watcher:127.0.0.1:50155 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2691133 T7117 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2691137 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2691137 T7119 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13ecfb55294000b, 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:662)
[junit4:junit4] 2>
[junit4:junit4] 2> 2691143 T7117 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2691146 T7208 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2b1c1f name:ZooKeeperConnection Watcher:127.0.0.1:50155/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2691146 T7117 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2691156 T7117 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2691346 T7140 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2691348 T7140 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[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:50192_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50192"}
[junit4:junit4] 2> 2691362 T7175 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> 2691362 T7191 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> 2691363 T7159 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> 2691363 T7139 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> 2691364 T7146 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> 2691364 T7208 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> 2691437 T7153 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 2691438 T7153 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:50192_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=779
[junit4:junit4] 2> 2691962 T7117 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50202_
[junit4:junit4] 2> 2691967 T7117 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50202_
[junit4:junit4] 2> 2691974 T7175 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> 2691975 T7139 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> 2691975 T7146 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> 2691978 T7191 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2691978 T7191 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> 2691979 T7208 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2691980 T7208 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> 2691980 T7159 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2691982 T7159 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> 2691985 T7175 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2691988 T7146 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2691988 T7139 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2691997 T7209 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.ShardSplitTest-jetty4-1369284380933\collection1
[junit4:junit4] 2> 2691997 T7209 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2691998 T7209 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2691998 T7209 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2692000 T7209 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.ShardSplitTest-jetty4-1369284380933\collection1\'
[junit4:junit4] 2> 2692002 T7209 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1369284380933/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2692002 T7209 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1369284380933/collection1/lib/README' to classloader
[junit4:junit4] 2> 2692050 T7209 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2692111 T7209 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2692112 T7209 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2692117 T7209 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2692704 T7209 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2692708 T7209 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2692710 T7209 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2692718 T7209 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2692754 T7209 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2692754 T7209 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.ShardSplitTest-jetty4-1369284380933\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty4\
[junit4:junit4] 2> 2692754 T7209 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@152643
[junit4:junit4] 2> 2692754 T7209 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2692755 T7209 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty4\
[junit4:junit4] 2> 2692755 T7209 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty4\index/
[junit4:junit4] 2> 2692755 T7209 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1369284366988\jetty4\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2692757 T7209 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty4\index
[junit4:junit4] 2> 2692760 T7209 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18f8c33 lockFactory=org.apache.lucene.store.NativeFSLockFactory@123b8f5),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2692761 T7209 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2692764 T7209 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2692764 T7209 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2692765 T7209 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2692766 T7209 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2692766 T7209 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2692767 T7209 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2692767 T7209 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2692768 T7209 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2692768 T7209 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2692777 T7209 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2692783 T7209 oass.SolrIndexSearcher.<init> Opening Searcher@350eb9 main
[junit4:junit4] 2> 2692783 T7209 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1369284366988\jetty4\tlog
[junit4:junit4] 2> 2692784 T7209 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2692784 T7209 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2692789 T7210 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@350eb9 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2692790 T7209 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2692791 T7209 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> ASYNC NEW_CORE C6885 name=collection1 org.apache.solr.core.SolrCore@78a148 url=http://127.0.0.1:50192/collection1 node=127.0.0.1:50192_ C6885_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:50192_, base_url=http://127.0.0.1:50192}
[junit4:junit4] 2> 2693121 T7194 C6885 P50192 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50174/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 2693121 T7194 C6885 P50192 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50192 START replicas=[http://127.0.0.1:50174/collection1/] nUpdates=100
[junit4:junit4] 2> 2693123 T7194 C6885 P50192 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 2693123 T7194 C6885 P50192 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 2693123 T7194 C6885 P50192 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 2693125 T7194 C6885 P50192 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 2693125 T7194 C6885 P50192 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 2693125 T7194 C6885 P50192 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50174/collection1/. core=collection1
[junit4:junit4] 2> 2693126 T7194 C6885 P50192 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C6886 name=collection1 org.apache.solr.core.SolrCore@485703 url=http://127.0.0.1:50174/collection1 node=127.0.0.1:50174_ C6886_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50174_, base_url=http://127.0.0.1:50174, leader=true}
[junit4:junit4] 2> 2693135 T7154 C6886 P50174 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 2693137 T7153 C6886 P50174 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2693140 T7153 C6886 P50174 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@834df4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8e9873),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2693141 T7153 C6886 P50174 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2693142 T7153 C6886 P50174 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@834df4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8e9873),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@834df4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8e9873),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2693142 T7153 C6886 P50174 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2693142 T7153 C6886 P50174 oass.SolrIndexSearcher.<init> Opening Searcher@1fa4175 realtime
[junit4:junit4] 2> 2693143 T7153 C6886 P50174 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2693143 T7153 C6886 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 2693144 T7194 C6885 P50192 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2693144 T7194 C6885 P50192 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 2693145 T7150 C6886 P50174 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2693145 T7150 C6886 P50174 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 2693146 T7194 C6885 P50192 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 2693146 T7194 C6885 P50192 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 2693146 T7194 C6885 P50192 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 2693148 T7151 C6886 P50174 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 2693149 T7194 C6885 P50192 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 2693150 T7194 C6885 P50192 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty3\index.20130523164623425
[junit4:junit4] 2> 2693150 T7194 C6885 P50192 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1f7fc8d lockFactory=org.apache.lucene.store.NativeFSLockFactory@187768f) fullCopy=false
[junit4:junit4] 2> 2693153 T7152 C6886 P50174 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 2693154 T7194 C6885 P50192 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 2693155 T7194 C6885 P50192 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 2693155 T7194 C6885 P50192 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 2693157 T7194 C6885 P50192 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2fdcae lockFactory=org.apache.lucene.store.NativeFSLockFactory@1196666),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2fdcae lockFactory=org.apache.lucene.store.NativeFSLockFactory@1196666),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2693158 T7194 C6885 P50192 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2693158 T7194 C6885 P50192 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 2693158 T7194 C6885 P50192 oass.SolrIndexSearcher.<init> Opening Searcher@1917247 main
[junit4:junit4] 2> 2693160 T7193 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1917247 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2693160 T7194 C6885 P50192 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty3\index.20130523164623425 [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty3\index.20130523164623425;done=true>>]
[junit4:junit4] 2> 2693160 T7194 C6885 P50192 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty3\index.20130523164623425
[junit4:junit4] 2> 2693160 T7194 C6885 P50192 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty3\index.20130523164623425
[junit4:junit4] 2> 2693161 T7194 C6885 P50192 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 2693161 T7194 C6885 P50192 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 2693161 T7194 C6885 P50192 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2693161 T7194 C6885 P50192 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2693163 T7194 C6885 P50192 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 2693914 T7140 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2693916 T7140 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[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:50202_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50202"}
[junit4:junit4] 2> 2693916 T7140 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 2693916 T7140 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 2693934 T7140 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[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:50192_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50192"}
[junit4:junit4] 2> 2693954 T7175 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> 2693955 T7191 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> 2693955 T7159 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> 2693956 T7139 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> 2693957 T7146 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> 2693957 T7208 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> 2694507 T7209 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2694507 T7209 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50202 collection:collection1 shard:shard2
[junit4:junit4] 2> 2694519 T7209 oasc.ZkController.register We are http://127.0.0.1:50202/collection1/ and leader is http://127.0.0.1:50183/collection1/
[junit4:junit4] 2> 2694519 T7209 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50202
[junit4:junit4] 2> 2694519 T7209 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 2694520 T7209 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C6887 name=collection1 org.apache.solr.core.SolrCore@aa3bb1 url=http://127.0.0.1:50202/collection1 node=127.0.0.1:50202_ C6887_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:50202_, base_url=http://127.0.0.1:50202}
[junit4:junit4] 2> 2694521 T7213 C6887 P50202 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 2694523 T7213 C6887 P50202 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 2694523 T7213 C6887 P50202 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 2694524 T7213 C6887 P50202 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2694523 T7209 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2694529 T7213 C6887 P50202 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2694530 T7117 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2694530 T7117 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2694532 T7117 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2694536 T7169 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 2694536 T7117 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2694538 T7117 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 2694538 T7117 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 2694539 T7117 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2695259 T7140 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2695260 T7140 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[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:50202_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50202"}
[junit4:junit4] 2> 2695272 T7175 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> 2695273 T7191 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> 2695273 T7159 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> 2695273 T7208 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> 2695273 T7146 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> 2695273 T7139 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> 2695392 T7169 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 2695392 T7169 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:50202_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=857
[junit4:junit4] 2> 2695396 T7117 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2696255 T7117 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C6887_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:50202_, base_url=http://127.0.0.1:50202}
[junit4:junit4] 2> 2697105 T7213 C6887 P50202 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50183/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 2697105 T7213 C6887 P50202 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50202 START replicas=[http://127.0.0.1:50183/collection1/] nUpdates=100
[junit4:junit4] 2> 2697105 T7213 C6887 P50202 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 2697105 T7213 C6887 P50202 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 2697105 T7213 C6887 P50202 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 2697106 T7213 C6887 P50202 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 2697106 T7213 C6887 P50202 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 2697106 T7213 C6887 P50202 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50183/collection1/. core=collection1
[junit4:junit4] 2> 2697107 T7213 C6887 P50202 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C6888 name=collection1 org.apache.solr.core.SolrCore@b0e886 url=http://127.0.0.1:50183/collection1 node=127.0.0.1:50183_ C6888_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50183_, base_url=http://127.0.0.1:50183, leader=true}
[junit4:junit4] 2> 2697116 T7170 C6888 P50183 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=2
[junit4:junit4] 2> 2697116 T7169 C6888 P50183 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2697116 T7117 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2697121 T7169 C6888 P50183 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@deaa83 lockFactory=org.apache.lucene.store.NativeFSLockFactory@973494),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2697122 T7169 C6888 P50183 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2697123 T7169 C6888 P50183 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@deaa83 lockFactory=org.apache.lucene.store.NativeFSLockFactory@973494),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@deaa83 lockFactory=org.apache.lucene.store.NativeFSLockFactory@973494),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2697123 T7169 C6888 P50183 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2697124 T7169 C6888 P50183 oass.SolrIndexSearcher.<init> Opening Searcher@169287e realtime
[junit4:junit4] 2> 2697125 T7169 C6888 P50183 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2697125 T7169 C6888 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 2697126 T7213 C6887 P50202 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2697126 T7213 C6887 P50202 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 2697127 T7167 C6888 P50183 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2697127 T7167 C6888 P50183 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 2697128 T7213 C6887 P50202 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 2697129 T7213 C6887 P50202 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 2697129 T7213 C6887 P50202 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 2697131 T7168 C6888 P50183 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 2697131 T7213 C6887 P50202 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 2697133 T7213 C6887 P50202 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty4\index.20130523164627407
[junit4:junit4] 2> 2697134 T7213 C6887 P50202 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@15085d5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1144977) fullCopy=false
[junit4:junit4] 2> 2697137 T7171 C6888 P50183 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 2697141 T7213 C6887 P50202 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 2697141 T7213 C6887 P50202 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 2697141 T7213 C6887 P50202 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> ASYNC NEW_CORE C6889 name=collection1 org.apache.solr.core.SolrCore@aa3bb1 url=http://127.0.0.1:50202/collection1 node=127.0.0.1:50202_ C6889_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:50202_, base_url=http://127.0.0.1:50202}
[junit4:junit4] 2> 2697151 T7213 C6889 P50202 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18f8c33 lockFactory=org.apache.lucene.store.NativeFSLockFactory@123b8f5),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18f8c33 lockFactory=org.apache.lucene.store.NativeFSLockFactory@123b8f5),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2697151 T7213 C6889 P50202 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2697151 T7213 C6889 P50202 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 2697152 T7213 C6889 P50202 oass.SolrIndexSearcher.<init> Opening Searcher@e72a4e main
[junit4:junit4] 2> 2697153 T7210 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e72a4e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2697154 T7213 C6889 P50202 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty4\index.20130523164627407 [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty4\index.20130523164627407;done=true>>]
[junit4:junit4] 2> 2697154 T7213 C6889 P50202 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty4\index.20130523164627407
[junit4:junit4] 2> 2697154 T7213 C6889 P50202 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: .\org.apache.solr.cloud.ShardSplitTest-1369284366988/jetty4\index.20130523164627407
[junit4:junit4] 2> 2697154 T7213 C6889 P50202 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 2697155 T7213 C6889 P50202 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 2697155 T7213 C6889 P50202 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2697155 T7213 C6889 P50202 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2697161 T7213 C6889 P50202 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 2697854 T7140 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2697854 T7140 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[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:50202_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50202"}
[junit4:junit4] 2> 2697864 T7175 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> 2697864 T7191 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> 2697865 T7159 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> 2697865 T7139 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> 2697865 T7146 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> 2697865 T7208 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> 2697976 T7117 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2697976 T7117 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C6890 name=collection1 org.apache.solr.core.SolrCore@19888d0 url=http://127.0.0.1:50162/collection1 node=127.0.0.1:50162_ C6890_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:50162_, base_url=http://127.0.0.1:50162, leader=true}
[junit4:junit4] 2> 2697985 T7131 C6890 P50162 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2697989 T7131 C6890 P50162 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a9515e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1784d1c),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2697990 T7131 C6890 P50162 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2697991 T7131 C6890 P50162 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a9515e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1784d1c),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a9515e lockFactory=org.apache.lucene.store.NativeFSLockFactory@1784d1c),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2697991 T7131 C6890 P50162 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2697991 T7131 C6890 P50162 oass.SolrIndexSearcher.<init> Opening Searcher@6bd25a main
[junit4:junit4] 2> 2697992 T7131 C6890 P50162 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2697993 T7143 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6bd25a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2697994 T7131 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> ASYNC NEW_CORE C6891 name=collection1 org.apache.solr.core.SolrCore@485703 url=http://127.0.0.1:50174/collection1 node=127.0.0.1:50174_ C6891_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50174_, base_url=http://127.0.0.1:50174, leader=true}
[junit4:junit4] 2> 2697999 T7153 C6891 P50174 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2698000 T7153 C6891 P50174 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@834df4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8e9873),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@834df4 lockFactory=org.apache.lucene.store.NativeFSLockFactory@8e9873),segFN=segments_3,generation=3}
[junit4:junit4] 2> 2698000 T7153 C6891 P50174 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 2698001 T7153 C6891 P50174 oass.SolrIndexSearcher.<init> Opening Searcher@17a3673 main
[junit4:junit4] 2> 2698001 T7153 C6891 P50174 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2698001 T7161 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@17a3673 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2698002 T7153 C6891 P50174 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:50192/collection1/, StdNode: http://127.0.0.1:50183/collection1/, StdNode: http://127.0.0.1:50202/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> ASYNC NEW_CORE C6892 name=collection1 org.apache.solr.core.SolrCore@b0e886 url=http://127.0.0.1:50183/collection1 node=127.0.0.1:50183_ C6892_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50183_, base_url=http://127.0.0.1:50183, leader=true}
[junit4:junit4] 2> 2698006 T7169 C6892 P50183 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2698006 T7169 C6892 P50183 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@deaa83 lockFactory=org.apache.lucene.store.NativeFSLockFactory@973494),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@deaa83 lockFactory=org.apache.lucene.store.NativeFSLockFactory@973494),segFN=segments_3,generation=3}
[junit4:junit4] 2> 2698007 T7169 C6892 P50183 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 2698007 T7169 C6892 P50183 oass.SolrIndexSearcher.<init> Opening Searcher@1c4e5e6 main
[junit4:junit4] 2> 2698008 T7169 C6892 P50183 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> ASYNC NEW_CORE C6893 name=collection1 org.apache.solr.core.SolrCore@78a148 url=http://127.0.0.1:50192/collection1 node=127.0.0.1:50192_ C6893_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50192_, base_url=http://127.0.0.1:50192}
[junit4:junit4] 2> 2698012 T7184 C6893 P50192 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2698014 T7177 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1c4e5e6 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2698015 T7169 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 2698015 T7184 C6893 P50192 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2fdcae lockFactory=org.apache.lucene.store.NativeFSLockFactory@1196666),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2fdcae lockFactory=org.apache.lucene.store.NativeFSLockFactory@1196666),segFN=segments_3,generation=3}
[junit4:junit4] 2> 2698016 T7184 C6893 P50192 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> C6889_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50202_, base_url=http://127.0.0.1:50202}
[junit4:junit4] 2> 2698016 T7201 C6889 P50202 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2698017 T7184 C6893 P50192 oass.SolrIndexSearcher.<init> Opening Searcher@1ffa564 main
[junit4:junit4] 2> 2698017 T7184 C6893 P50192 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2698017 T7201 C6889 P50202 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18f8c33 lockFactory=org.apache.lucene.store.NativeFSLockFactory@123b8f5),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@18f8c33 lockFactory=org.apache.lucene.store.NativeFSLockFactory@123b8f5),segFN=segments_3,generation=3}
[junit4:junit4] 2> 2698018 T7201 C6889 P50202 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 2698017 T7193 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ffa564 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2698018 T7201 C6889 P50202 oass.SolrIndexSearcher.<init> Opening Searcher@95d74f main
[junit4:junit4] 2> 2698019 T7184 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 2698019 T7201 C6889 P50202 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2698020 T7210 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@95d74f main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2698021 T7201 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 2698021 T7153 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 22
[junit4:junit4] 2> 2698022 T7117 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2698025 T7150 C6891 P50174 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 2698027 T7186 C6893 P50192 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 2698028 T7166 C6892 P50183 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 2698030 T7203 C6889 P50202 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 2699747 T7135 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435798748549611520)} 0 4
[junit4:junit4] 2> 2699763 T7199 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435798748556951552&update.from=http://127.0.0.1:50183/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435798748556951552)} 0 2
[junit4:junit4] 2> 2699774 T7183 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435798748567437312&update.from=http://127.0.0.1:50174/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435798748567437312)} 0 5
[junit4:junit4] 2> 2699776 T7154 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1435798748567437312)} 0 15
[junit4:junit4] 2> 2699778 T7170 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435798748556951552)} 0 27
[junit4:junit4] 2> 2699783 T7130 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1435798748589457408)]} 0 2
[junit4:junit4] 2> 2699789 T7201 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1435798748593651712)]} 0 1
[junit4:junit4] 2> 2699792 T7169 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1435798748593651712)]} 0 7
[junit4:junit4] 2> 2699795 T7131 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1435798748603088896)]} 0 1
[junit4:junit4] 2> 2699803 T7185 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1435798748607283200)]} 0 0
[junit4:junit4] 2> 2699804 T7153 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1435798748607283200)]} 0 5
[junit4:junit4] 2> 2699808 T7132 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1435798748616720384)]} 0 0
[junit4:junit4] 2> 2699814 T7186 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1435798748620914688)]} 0 1
[junit4:junit4] 2> 2699815 T7150 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1435798748620914688)]} 0 4
[junit4:junit4] 2> 2699818 T7133 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1435798748627206144)]} 0 0
[junit4:junit4] 2> 2699828 T7203 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1435798748635594752)]} 0 0
[junit4:junit4] 2> 2699831 T7166 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!3 (1435798748635594752)]} 0 7
[junit4:junit4] 2> 2699832 T7151 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3]} 0 10
[junit4:junit4] 2> 2699836 T7134 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1435798748645031936)]} 0 0
[junit4:junit4] 2> 2699846 T7202 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1435798748653420544)]} 0 1
[junit4:junit4] 2> 2699848 T7167 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!4 (1435798748653420544)]} 0 6
[junit4:junit4] 2> 2699849 T7152 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4]} 0 9
[junit4:junit4] 2> 2699852 T7135 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1435798748662857728)]} 0 1
[junit4:junit4] 2> 2699862 T7204 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1435798748670197760)]} 0 1
[junit4:junit4] 2> 2699864 T7168 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!5 (1435798748670197760)]} 0 5
[junit4:junit4] 2> 2699864 T7154 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5]} 0 8
[junit4:junit4] 2> 2699869 T7130 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1435798748679634944)]} 0 1
[junit4:junit4] 2> 2699878 T7187 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1435798748685926400)]} 0 1
[junit4:junit4] 2> 2699879 T7155 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!6 (1435798748685926400)]} 0 5
[junit4:junit4] 2> 2699880 T7171 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6]} 0 9
[junit4:junit4] 2> 2699884 T7131 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1435798748696412160)]} 0 1
[junit4:junit4] 2> 2699894 T7182 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1435798748702703616)]} 0 1
[junit4:junit4] 2> 2699895 T7153 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!7 (1435798748702703616)]} 0 6
[junit4:junit4] 2> 2699896 T7170 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7]} 0 10
[junit4:junit4] 2> 2699900 T7132 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1435798748713189376)]} 0 1
[junit4:junit4] 2> 2699906 T7183 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1435798748716335104)]} 0 0
[junit4:junit4] 2> 2699907 T7150 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1435798748716335104)]} 0 4
[junit4:junit4] 2> 2699911 T7133 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1435798748724723712)]} 0 1
[junit4:junit4] 2> 2699918 T7184 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1435798748728918016)]} 0 1
[junit4:junit4] 2> 2699919 T7151 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1435798748728918016)]} 0 4
[junit4:junit4] 2> 2699922 T7134 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1435798748736258048)]} 0 1
[junit4:junit4] 2> 2699928 T7185 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1435798748739403776)]} 0 1
[junit4:junit4] 2> 2699929 T7152 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1435798748739403776)]} 0 4
[junit4:junit4] 2> 2699932 T7135 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1435798748746743808)]} 0 1
[junit4:junit4] 2> 2699941 T7197 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1435798748754083840)]} 0 0
[junit4:junit4] 2> 2699943 T7169 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!11 (1435798748754083840)]} 0 5
[junit4:junit4] 2> 2699944 T7154 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11]} 0 8
[junit4:junit4] 2> 2699947 T7130 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1435798748762472448)]} 0 1
[junit4:junit4] 2> 2699955 T7199 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1435798748768763904)]} 0 0
[junit4:junit4] 2> 2699957 T7166 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!12 (1435798748768763904)]} 0 5
[junit4:junit4] 2> 2699958 T7155 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12]} 0 8
[junit4:junit4] 2> 2699961 T7131 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1435798748777152512)]} 0 0
[junit4:junit4] 2> 2699971 T7186 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1435798748783443968)]} 0 0
[junit4:junit4] 2> 2699972 T7153 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!13 (1435798748783443968)]} 0 6
[junit4:junit4] 2> 2699973 T7167 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13]} 0 9
[junit4:junit4] 2> 2699977 T7132 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1435798748792881152)]} 0 1
[junit4:junit4] 2> 2699986 T7201 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1435798748800221184)]} 0 1
[junit4:junit4] 2> 2699986 T7168 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!14 (1435798748800221184)]} 0 4
[junit4:junit4] 2> 2699987 T7150 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14]} 0 7
[junit4:junit4] 2> 2699992 T7133 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1435798748809658368)]} 0 1
[junit4:junit4] 2> 2700002 T7187 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1435798748815949824)]} 0 1
[junit4:junit4] 2> 2700002 T7151 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!15 (1435798748815949824)]} 0 5
[junit4:junit4] 2> 2700004 T7171 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15]} 0 9
[junit4:junit4] 2> 2700007 T7134 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1435798748825387008)]} 0 0
[junit4:junit4] 2> 2700017 T7182 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1435798748831678464)]} 0 1
[junit4:junit4] 2> 2700018 T7152 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1435798748831678464)]} 0 5
[junit4:junit4] 2> 2700019 T7170 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16]} 0 9
[junit4:junit4] 2> 2700023 T7135 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1435798748842164224)]} 0 1
[junit4:junit4] 2> 2700031 T7203 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1435798748846358528)]} 0 1
[junit4:junit4] 2> 2700032 T7169 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1435798748846358528)]} 0 5
[junit4:junit4] 2> 2700037 T7130 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1435798748856844288)]} 0 1
[junit4:junit4] 2> 2700042 T7183 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1435798748859990016)]} 0 0
[junit4:junit4] 2> 2700044 T7154 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1435798748859990016)]} 0 5
[junit4:junit4] 2> 2700048 T7131 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1435798748868378624)]} 0 1
[junit4:junit4] 2> 2700067 T7184 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1435798748884107264)]} 0 1
[junit4:junit4] 2> 2700068 T7155 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1435798748884107264)]} 0 7
[junit4:junit4] 2> 2700072 T7132 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1435798748893544448)]} 0 1
[junit4:junit4] 2> 2700080 T7202 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1435798748899835904)]} 0 1
[junit4:junit4] 2> 2700082 T7166 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!20 (1435798748899835904)]} 0 5
[junit4:junit4] 2> 2700083 T7153 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20]} 0 9
[junit4:junit4] 2> 2700086 T7133 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1435798748907175936)]} 0 1
[junit4:junit4] 2> 2700092 T7185 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1435798748911370240)]} 0 1
[junit4:junit4] 2> 2700093 T7150 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1435798748911370240)]} 0 5
[junit4:junit4] 2> 2700097 T7134 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1435798748919758848)]} 0 1
[junit4:junit4] 2> 2700106 T7186 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1435798748925001728)]} 0 0
[junit4:junit4] 2> 2700108 T7151 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!22 (1435798748925001728)]} 0 6
[junit4:junit4] 2> 2700109 T7167 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22]} 0 10
[junit4:junit4] 2> 2700112 T7135 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1435798748935487488)]} 0 1
[junit4:junit4] 2> 2700121 T7204 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1435798748941778944)]} 0 1
[junit4:junit4] 2> 2700122 T7168 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!23 (1435798748941778944)]} 0 4
[junit4:junit4] 2> 2700124 T7152 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23]} 0 9
[junit4:junit4] 2> 2700128 T7131 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1435798748952264704)]} 0 1
[junit4:junit4] 2> 2700133 T7197 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1435798748955410432)]} 0 0
[junit4:junit4] 2> 2700135 T7171 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1435798748955410432)]} 0 5
[junit4:junit4] 2> 2700139 T7132 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1435798748963799040)]} 0 1
[junit4:junit4] 2> 2700144 T7187 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1435798748966944768)]} 0 0
[junit4:junit4] 2> 2700145 T7154 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1435798748966944768)]} 0 4
[junit4:junit4] 2> 2700149 T7133 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1435798748974284800)]} 0 0
[junit4:junit4] 2> 2700156 T7199 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1435798748978479104)]} 0 0
[junit4:junit4] 2> 2700159 T7170 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1435798748978479104)]} 0 6
[junit4:junit4] 2> 2700162 T7134 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1435798748987916288)]} 0 1
[junit4:junit4] 2> 2700168 T7182 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1435798748991062016)]} 0 1
[junit4:junit4] 2> 2700169 T7155 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1435798748991062016)]} 0 4
[junit4:junit4] 2> 2700173 T7130 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1435798748998402048)]} 0 1
[junit4:junit4] 2> 2700179 T7183 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1435798749002596352)]} 0 1
[junit4:junit4] 2> 2700180 T7153 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1435798749002596352)]} 0 5
[junit4:junit4] 2> 2700184 T7135 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1435798749010984960)]} 0 1
[junit4:junit4] 2> 2700190 T7203 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1435798749014130688)]} 0 0
[junit4:junit4] 2> 2700191 T7166 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1435798749014130688)]} 0 5
[junit4:junit4] 2> 2700195 T7131 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1435798749022519296)]} 0 0
[junit4:junit4] 2> 2700201 T7202 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1435798749024616448)]} 0 0
[junit4:junit4] 2> 2700202 T7167 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1435798749024616448)]} 0 5
[junit4:junit4] 2> 2700206 T7132 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1435798749034053632)]} 0 1
[junit4:junit4] 2> 2700214 T7204 C6889 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1435798749040345088)]} 0 0
[junit4:junit4] 2> 2700216 T7168 C6892 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1435798749040345088)]} 0 5
[junit4:junit4] 2> 2700217 T7150 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31]} 0 8
[junit4:junit4] 2> 2700221 T7133 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1435798749049782272)]} 0 0
[junit4:junit4] 2> 2700226 T7184 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1435798749052928000)]} 0 0
[junit4:junit4] 2> 2700228 T7152 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1435798749052928000)]} 0 5
[junit4:junit4] 2> 2700232 T7134 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1435798749061316608)]} 0 1
[junit4:junit4] 2> 2700238 T7186 C6893 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1435798749065510912)]} 0 1
[junit4:junit4] 2> 2700239 T7154 C6891 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1435798749065510912)]} 0 4
[junit4:junit4] 2> 2700242 T7130 C6890 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1435798749071802368)]} 0 1
[junit4:junit4] 2> ASYNC NEW_CORE C6894 name=collection1 org.apache.solr.core.SolrCore@78a148 url=http://127.0.0.1:50192/collection1 node=127.0.0.1:50192_ C6894_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50192_, base_url=http://127.0.0.1:50192}
[junit4:junit4] 2> 2700264 T7187 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1435798749091725312)]} 0 1
[junit4:junit4] 2> ASYNC NEW_CORE C6895 name=collection1 org.apache.solr.core.SolrCore@485703 url=http://127.0.0.1:50174/collection1 node=127.0.0.1:50174_ C6895_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50174_, base_url=http://127.0.0.1:50174, leader=true}
[junit4:junit4] 2> 2700266 T7155 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!34 (1435798749091725312)]} 0 5
[junit4:junit4] 2> ASYNC NEW_CORE C6896 name=collection1 org.apache.solr.core.SolrCore@b0e886 url=http://127.0.0.1:50183/collection1 node=127.0.0.1:50183_ C6896_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50183_, base_url=http://127.0.0.1:50183, leader=true}
[junit4:junit4] 2> 2700267 T7171 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34]} 0 22
[junit4:junit4] 2> ASYNC NEW_CORE C6897 name=collection1 org.apache.solr.core.SolrCore@19888d0 url=http://127.0.0.1:50162/collection1 node=127.0.0.1:50162_ C6897_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:50162_, base_url=http://127.0.0.1:50162, leader=true}
[junit4:junit4] 2> 2700272 T7135 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1435798749102211072)]} 0 1
[junit4:junit4] 2> 2700288 T7182 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1435798749117939712)]} 0 0
[junit4:junit4] 2> 2700289 T7153 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1435798749117939712)]} 0 3
[junit4:junit4] 2> 2700291 T7131 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1435798749123182592)]} 0 0
[junit4:junit4] 2> 2700298 T7183 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1435798749126328320)]} 0 1
[junit4:junit4] 2> 2700298 T7151 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1435798749126328320)]} 0 4
[junit4:junit4] 2> 2700300 T7132 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1435798749132619776)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C6898 name=collection1 org.apache.solr.core.SolrCore@aa3bb1 url=http://127.0.0.1:50202/collection1 node=127.0.0.1:50202_ C6898_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50202_, base_url=http://127.0.0.1:50202}
[junit4:junit4] 2> 2700307 T7197 C6898 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1435798749136814080)]} 0 0
[junit4:junit4] 2> 2700308 T7169 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1435798749136814080)]} 0 5
[junit4:junit4] 2> 2700310 T7133 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1435798749143105536)]} 0 0
[junit4:junit4] 2> 2700315 T7201 C6898 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1435798749146251264)]} 0 0
[junit4:junit4] 2> 2700317 T7170 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1435798749146251264)]} 0 4
[junit4:junit4] 2> 2700319 T7134 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1435798749152542720)]} 0 0
[junit4:junit4] 2> 2700327 T7185 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1435798749156737024)]} 0 1
[junit4:junit4] 2> 2700328 T7150 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!39 (1435798749156737024)]} 0 5
[junit4:junit4] 2> 2700328 T7166 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39]} 0 7
[junit4:junit4] 2> 2700332 T7130 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1435798749165125632)]} 0 1
[junit4:junit4] 2> 2700338 T7199 C6898 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1435798749168271360)]} 0 1
[junit4:junit4] 2> 2700339 T7167 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1435798749168271360)]} 0 5
[junit4:junit4] 2> 2700343 T7135 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41 (1435798749177708544)]} 0 1
[junit4:junit4] 2> 2700353 T7184 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1435798749185048576)]} 0 1
[junit4:junit4] 2> 2700354 T7152 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!41 (1435798749185048576)]} 0 5
[junit4:junit4] 2> 2700355 T7168 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41]} 0 9
[junit4:junit4] 2> 2700358 T7131 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1435798749192388608)]} 0 1
[junit4:junit4] 2> 2700368 T7186 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1435798749199728640)]} 0 1
[junit4:junit4] 2> 2700369 T7154 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!42 (1435798749199728640)]} 0 5
[junit4:junit4] 2> 2700370 T7171 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42]} 0 9
[junit4:junit4] 2> 2700375 T7132 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1435798749211262976)]} 0 1
[junit4:junit4] 2> 2700381 T7203 C6898 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1435798749214408704)]} 0 1
[junit4:junit4] 2> 2700383 T7169 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1435798749214408704)]} 0 5
[junit4:junit4] 2> 2700387 T7133 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1435798749223845888)]} 0 1
[junit4:junit4] 2> 2700397 T7187 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1435798749229088768)]} 0 1
[junit4:junit4] 2> 2700398 T7155 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!44 (1435798749229088768)]} 0 6
[junit4:junit4] 2> 2700400 T7170 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44]} 0 10
[junit4:junit4] 2> 2700403 T7134 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1435798749240623104)]} 0 1
[junit4:junit4] 2> 2700413 T7182 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1435798749245865984)]} 0 1
[junit4:junit4] 2> 2700414 T7153 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1435798749245865984)]} 0 7
[junit4:junit4] 2> 2700418 T7130 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1435798749256351744)]} 0 0
[junit4:junit4] 2> 2700426 T7202 C6898 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1435798749261594624)]} 0 1
[junit4:junit4] 2> 2700428 T7166 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1435798749261594624)]} 0 6
[junit4:junit4] 2> 2700432 T7135 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1435798749271031808)]} 0 1
[junit4:junit4] 2> 2700443 T7183 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1435798749278371840)]} 0 1
[junit4:junit4] 2> 2700445 T7151 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!47 (1435798749278371840)]} 0 7
[junit4:junit4] 2> 2700446 T7167 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47]} 0 10
[junit4:junit4] 2> 2700451 T7131 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1435798749289906176)]} 0 1
[junit4:junit4] 2> 2700459 T7185 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1435798749296197632)]} 0 1
[junit4:junit4] 2> 2700461 T7150 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1435798749296197632)]} 0 6
[junit4:junit4] 2> 2700468 T7132 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1435798749307731968)]} 0 1
[junit4:junit4] 2> 2700475 T7204 C6898 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1435798749314023424)]} 0 0
[junit4:junit4] 2> 2700476 T7168 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1435798749314023424)]} 0 3
[junit4:junit4] 2> 2700479 T7133 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1435798749320314880)]} 0 0
[junit4:junit4] 2> 2700485 T7197 C6898 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1435798749323460608)]} 0 0
[junit4:junit4] 2> 2700486 T7171 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1435798749323460608)]} 0 4
[junit4:junit4] 2> 2700488 T7134 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1435798749329752064)]} 0 0
[junit4:junit4] 2> 2700497 T7184 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1435798749336043520)]} 0 1
[junit4:junit4] 2> 2700498 T7152 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!51 (1435798749336043520)]} 0 4
[junit4:junit4] 2> 2700498 T7169 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51]} 0 6
[junit4:junit4] 2> 2700502 T7130 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1435798749344432128)]} 0 0
[junit4:junit4] 2> 2700508 T7201 C6898 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1435798749347577856)]} 0 0
[junit4:junit4] 2> 2700509 T7170 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1435798749347577856)]} 0 4
[junit4:junit4] 2> 2700513 T7135 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1435798749355966464)]} 0 0
[junit4:junit4] 2> 2700516 T7186 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1435798749358063616)]} 0 0
[junit4:junit4] 2> 2700517 T7154 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1435798749358063616)]} 0 2
[junit4:junit4] 2> 2700520 T7132 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1435798749363306496)]} 0 0
[junit4:junit4] 2> 2700527 T7187 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1435798749367500800)]} 0 0
[junit4:junit4] 2> 2700527 T7155 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1435798749367500800)]} 0 3
[junit4:junit4] 2> 2700535 T7133 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55 (1435798749379035136)]} 0 0
[junit4:junit4] 2> 2700543 T7199 C6898 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1435798749384278016)]} 0 0
[junit4:junit4] 2> 2700544 T7166 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!55 (1435798749384278016)]} 0 5
[junit4:junit4] 2> 2700544 T7153 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55]} 0 6
[junit4:junit4] 2> 2700547 T7134 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1435798749391618048)]} 0 0
[junit4:junit4] 2> 2700552 T7203 C6898 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1435798749393715200)]} 0 0
[junit4:junit4] 2> 2700553 T7167 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1435798749393715200)]} 0 4
[junit4:junit4] 2> 2700556 T7130 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1435798749401055232)]} 0 0
[junit4:junit4] 2> 2700565 T7202 C6898 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1435798749407346688)]} 0 0
[junit4:junit4] 2> 2700566 T7171 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!57 (1435798749407346688)]} 0 4
[junit4:junit4] 2> 2700567 T7151 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57]} 0 7
[junit4:junit4] 2> 2700570 T7135 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58 (1435798749415735296)]} 0 0
[junit4:junit4] 2> 2700578 T7182 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1435798749420978176)]} 0 0
[junit4:junit4] 2> 2700579 T7150 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!58 (1435798749420978176)]} 0 4
[junit4:junit4] 2> 2700580 T7169 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58]} 0 8
[junit4:junit4] 2> 2700583 T7131 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1435798749429366784)]} 0 0
[junit4:junit4] 2> 2700591 T7183 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1435798749435658240)]} 0 0
[junit4:junit4] 2> 2700592 T7152 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!59 (1435798749435658240)]} 0 3
[junit4:junit4] 2> 2700593 T7170 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59]} 0 7
[junit4:junit4] 2> 2700595 T7132 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1435798749441949696)]} 0 0
[junit4:junit4] 2> 2700602 T7185 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1435798749447192576)]} 0 0
[junit4:junit4] 2> 2700603 T7154 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!60 (1435798749447192576)]} 0 3
[junit4:junit4] 2> 2700605 T7166 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60]} 0 8
[junit4:junit4] 2> 2700606 T7133 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1435798749453484032)]} 0 0
[junit4:junit4] 2> 2700612 T7184 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1435798749457678336)]} 0 0
[junit4:junit4] 2> 2700613 T7155 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1435798749457678336)]} 0 3
[junit4:junit4] 2> 2700617 T7134 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62 (1435798749465018368)]} 0 0
[junit4:junit4] 2> 2700622 T7186 C6894 P50192 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!62 (1435798749468164096)]} 0 0
[junit4:junit4] 2> 2700623 T7151 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62 (1435798749468164096)]} 0 4
[junit4:junit4] 2> 2700627 T7130 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63 (1435798749475504128)]} 0 0
[junit4:junit4] 2> 2700635 T7197 C6898 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!63 (1435798749481795584)]} 0 0
[junit4:junit4] 2> 2700636 T7167 C6896 P50183 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50174/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!63 (1435798749481795584)]} 0 3
[junit4:junit4] 2> 2700637 T7150 C6895 P50174 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63]} 0 8
[junit4:junit4] 2> 2700639 T7135 C6897 P50162 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!64 (1435798749488087040)]} 0 0
[junit4:junit4] 2> 2700649 T7201 C6898 P50202 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50183/coll
[...truncated too long message...]
27.0.0.1:50155 50155
[junit4:junit4] 2> 2712553 T7208 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2713678 T7208 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> 2713679 T7208 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2713680 T7117 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 50162
[junit4:junit4] 2> 2713696 T7117 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 2713696 T7117 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:50155 50155
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=1E54C08CE37E2BE0 -Dtests.slow=true -Dtests.locale=pt -Dtests.timezone=Pacific/Auckland -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR 37.0s | ShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:50174 returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([1E54C08CE37E2BE0:9FB24E9494214BDC]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:133)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:662)
[junit4:junit4] 2> 2713707 T7117 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=PostingsFormat(name=SimpleText), _version_=PostingsFormat(name=Lucene41WithOrds)}, docValues:{}, sim=DefaultSimilarity, locale=pt, timezone=Pacific/Auckland
[junit4:junit4] 2> NOTE: Windows 7 6.1 x86/Sun Microsystems Inc. 1.6.0_45 (32-bit)/cpus=2,threads=4,free=299054576,total=460988416
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestDynamicFieldResource, TestDFRSimilarityFactory, UpdateRequestProcessorFactoryTest, TestJmxMonitoredMap, TestStressLucene, SampleTest, TestSchemaNameResource, TestManagedSchemaFieldResource, TestDistributedSearch, CollectionsAPIDistributedZkTest, TestReplicationHandler, ZkNodePropsTest, QueryElevationComponentTest, TestSolrXml, AnalysisAfterCoreReloadTest, TestTrie, TestLRUCache, TestClassNameShortening, HardAutoCommitTest, TestOmitPositions, SolrCoreCheckLockOnStartupTest, ShowFileRequestHandlerTest, BadIndexSchemaTest, BasicZkTest, TestReversedWildcardFilterFactory, AutoCommitTest, ChaosMonkeySafeLeaderTest, DirectUpdateHandlerOptimizeTest, TestCloudManagedSchemaAddField, SearchHandlerTest, TestCSVLoader, IndexBasedSpellCheckerTest, TestQueryTypes, TestNumberUtils, DistributedTermsComponentTest, MBeansHandlerTest, EchoParamsTest, TestElisionMultitermQuery, DocumentBuilderTest, CircularListTest, SuggesterFSTTest, UpdateParamsTest, TestCollationKeyRangeQueries, TestCopyFieldCollectionResource, SortByFunctionTest, CoreAdminHandlerTest, SolrPluginUtilsTest, TestCharFilters, TestPhraseSuggestions, TestSolrQueryParserResource, TestFunctionQuery, SoftAutoCommitTest, WordBreakSolrSpellCheckerTest, TestShardHandlerFactory, RequiredFieldsTest, BadCopyFieldTest, TestReload, TestStressRecovery, TestLMJelinekMercerSimilarityFactory, TestPluginEnable, TestPseudoReturnFields, TestDynamicFieldCollectionResource, DirectSolrConnectionTest, URLClassifyProcessorTest, TestSchemaResource, BasicDistributedZk2Test, ConvertedLegacyTest, SolrIndexConfigTest, UUIDFieldTest, SignatureUpdateProcessorFactoryTest, BasicFunctionalityTest, TestRangeQuery, NumericFieldsTest, SolrCmdDistributorTest, DistributedQueryElevationComponentTest, TestJmxIntegration, ZkSolrClientTest, TestQuerySenderNoQuery, SolrTestCaseJ4Test, TestSolrQueryParser, TermsComponentTest, TestPHPSerializedResponseWriter, BinaryUpdateRequestHandlerTest, QueryEqualityTest, IndexSchemaRuntimeFieldTest, TestIndexingPerformance, TestZkChroot, TestCSVResponseWriter, ZkCLITest, TestLMDirichletSimilarityFactory, TestCodecSupport, ShardRoutingCustomTest, TestFieldCollectionResource, OverseerCollectionProcessorTest, PathHierarchyTokenizerFactoryTest, TestPartialUpdateDeduplication, OutputWriterTest, SliceStateUpdateTest, XsltUpdateRequestHandlerTest, SOLR749Test, DateMathParserTest, TestSurroundQueryParser, SolrIndexSplitterTest, ResourceLoaderTest, TestSweetSpotSimilarityFactory, TestFiltering, TestFieldTypeCollectionResource, TestJoin, SimplePostToolTest, TestUniqueKeyFieldResource, PluginInfoTest, PrimitiveFieldTypeTest, TestExtendedDismaxParser, TestStressReorder, DocValuesTest, DirectUpdateHandlerTest, AlternateDirectoryTest, TestDocSet, DistanceFunctionTest, OpenExchangeRatesOrgProviderTest, TestRemoteStreaming, RequestHandlersTest, TestXIncludeConfig, CachingDirectoryFactoryTest, CopyFieldTest, TestSystemIdResolver, TestUtils, SyncSliceTest, TestFoldingMultitermQuery, LegacyHTMLStripCharFilterTest, ChaosMonkeyShardSplitTest, PreAnalyzedUpdateProcessorTest, HighlighterConfigTest, TestCollationField, FieldMutatingUpdateProcessorTest, TermVectorComponentDistributedTest, IndexReaderFactoryTest, RegexBoostProcessorTest, BasicDistributedZkTest, UnloadDistributedZkTest, OpenCloseCoreStressTest, OverseerTest, LeaderElectionIntegrationTest, ShardRoutingTest, RecoveryZkTest, FullSolrCloudDistribCmdsTest, ClusterStateUpdateTest, TestRandomFaceting, LeaderElectionTest, TestRandomDVFaceting, TestDistributedGrouping, TestFaceting, TestRecovery, TestHashPartitioner, DistributedSpellCheckComponentTest, ZkControllerTest, TestRealTimeGet, TestMultiCoreConfBootstrap, TestStressVersions, TestCoreContainer, SimpleFacetsTest, TestSolr4Spatial, SolrCoreTest, StatsComponentTest, SpellCheckComponentTest, TestGroupingSearch, PeerSyncTest, TestSort, TestLazyCores, TestBadConfig, TestIndexSearcher, HighlighterTest, CurrencyFieldOpenExchangeTest, CurrencyFieldXmlFileTest, TestCoreDiscovery, SpellCheckCollatorTest, SolrRequestParserTest, SuggesterTSTTest, SuggesterTest, SpatialFilterTest, SuggesterWFSTTest, PolyFieldTest, NoCacheHeaderTest, SchemaVersionSpecificBehaviorTest, TestUpdate, TestAtomicUpdateErrorCases, TestWordDelimiterFilterFactory, DefaultValueUpdateProcessorTest, StatelessScriptUpdateProcessorFactoryTest, DocValuesMultiTest, TestSolrDeletionPolicy1, SolrInfoMBeanTest, DebugComponentTest, CacheHeaderTest, LukeRequestHandlerTest, DisMaxRequestHandlerTest, TestQueryUtils, StandardRequestHandlerTest, TestWriterPerf, DirectSolrSpellCheckerTest, DocumentAnalysisRequestHandlerTest, FileBasedSpellCheckerTest, XmlUpdateRequestHandlerTest, TestValueSourceCache, TermVectorComponentTest, MoreLikeThisHandlerTest, FieldAnalysisRequestHandlerTest, TestArbitraryIndexDir, FastVectorHighlighterTest, LoggingHandlerTest, IndexSchemaTest, ReturnFieldsTest, JSONWriterTest, QueryParsingTest, TestAnalyzedSuggestions, UniqFieldsUpdateProcessorFactoryTest, JsonLoaderTest, PingRequestHandlerTest, CSVRequestHandlerTest, TestComponentsName, CoreContainerCoreInitFailuresTest, TestBinaryResponseWriter, TestLFUCache, TestPropInject, TestQuerySenderListener, TestPropInjectDefaults, TestSolrIndexConfig, ResponseLogComponentTest, BadComponentTest, TestMergePolicyConfig, TestSolrDeletionPolicy2, MultiTermTest, TestBinaryField, TestSearchPerf, MinimalSchemaTest, TestConfig, TestFuzzyAnalyzedSuggestions, ExternalFileFieldSortTest, TestSolrCoreProperties, TestPostingsSolrHighlighter, NotRequiredUniqueKeyTest, TestLuceneMatchVersion, SpellPossibilityIteratorTest, SynonymTokenizerTest, TestPerFieldSimilarity, TestIBSimilarityFactory, TestBM25SimilarityFactory, TestDefaultSimilarityFactory, TestFastWriter, TimeZoneUtilsTest, TestFastOutputStream, ScriptEngineTest, TestFastLRUCache, ChaosMonkeyNothingIsSafeTest, TestSolrXMLSerializer, PreAnalyzedFieldTest, PrimUtilsTest, TestSuggestSpellingConverter, DateFieldTest, SpellingQueryConverterTest, DOMUtilTest, RAMDirectoryFactoryTest, ClusterStateTest, TestSolrJ, TestDocumentBuilder, SliceStateTest, SystemInfoHandlerTest, FileUtilsTest, TestRTGBase, AliasIntegrationTest, ShardSplitTest]
[junit4:junit4] Completed in 37.04s, 1 test, 1 error <<< FAILURES!
[...truncated 48 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:386: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:366: 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:1243: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\lucene\common-build.xml:887: There were test failures: 296 suites, 1234 tests, 1 error, 20 ignored (14 assumptions)
Total time: 69 minutes 17 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.6.0_45 -server -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure