You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/25 10:34:03 UTC
[JENKINS] Lucene-Solr-trunk-Windows (64bit/jdk1.7.0_25) - Build #
2968 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Windows/2968/
Java: 64bit/jdk1.7.0_25 -XX:-UseCompressedOops -XX:+UseParallelGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:64493 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:64493 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([90D8ADA3A986CE32:113E23BBDED9AE0E]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:150)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:724)
Build Log:
[...truncated 9233 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 158897 T443 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 158902 T443 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\solrtest-ShardSplitTest-1372146885366
[junit4:junit4] 2> 158904 T443 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 158905 T444 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 158984 T443 oasc.ZkTestServer.run start zk server on port:64474
[junit4:junit4] 2> 158986 T443 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 159001 T450 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2b3b9aab name:ZooKeeperConnection Watcher:127.0.0.1:64474 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 159002 T443 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 159002 T443 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 159010 T443 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 159017 T452 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@587894a6 name:ZooKeeperConnection Watcher:127.0.0.1:64474/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 159017 T443 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 159017 T443 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 159029 T443 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 159033 T443 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 159039 T443 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 159043 T443 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 159044 T443 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 159054 T443 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 159054 T443 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 159060 T443 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 159060 T443 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 159065 T443 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 159065 T443 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 159068 T443 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 159069 T443 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 159075 T443 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 159076 T443 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 159089 T443 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 159090 T443 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 159096 T443 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 159096 T443 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 159101 T443 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 159101 T443 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 159107 T445 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f7a53e2fd0001, 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:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 159424 T443 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 159429 T443 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:64481
[junit4:junit4] 2> 159430 T443 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 159430 T443 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 159430 T443 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1372146885570
[junit4:junit4] 2> 159431 T443 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1372146885570\solr.xml
[junit4:junit4] 2> 159431 T443 oasc.CoreContainer.<init> New CoreContainer 119848814
[junit4:junit4] 2> 159431 T443 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1372146885570\'
[junit4:junit4] 2> 159432 T443 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1372146885570\'
[junit4:junit4] 2> 159517 T443 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 159518 T443 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 159518 T443 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 159519 T443 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 159519 T443 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 159519 T443 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 159520 T443 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 159520 T443 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 159520 T443 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 159520 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 159527 T443 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 159527 T443 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:64474/solr
[junit4:junit4] 2> 159527 T443 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 159530 T443 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 159540 T463 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2bd3ec8 name:ZooKeeperConnection Watcher:127.0.0.1:64474 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 159541 T443 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 159546 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 159555 T443 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 159559 T465 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6ed71b42 name:ZooKeeperConnection Watcher:127.0.0.1:64474/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 159560 T443 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 159563 T443 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 159569 T443 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 159573 T443 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 159577 T443 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:64481_
[junit4:junit4] 2> 159579 T443 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:64481_
[junit4:junit4] 2> 159585 T443 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 159596 T443 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 159601 T443 oasc.Overseer.start Overseer (id=89925018279804931-127.0.0.1:64481_-n_0000000000) starting
[junit4:junit4] 2> 159609 T443 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 159622 T443 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 159622 T467 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 159627 T443 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 159630 T443 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 159633 T466 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 159636 T468 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 159636 T468 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 160819 T466 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 160820 T466 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:64481_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64481"}
[junit4:junit4] 2> 160820 T466 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 160820 T466 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 160838 T465 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> 161211 T468 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1372146885570\collection1
[junit4:junit4] 2> 161211 T468 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 161213 T468 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 161214 T468 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 161217 T468 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1372146885570\collection1\'
[junit4:junit4] 2> 161219 T468 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1372146885570/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 161219 T468 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1372146885570/collection1/lib/README' to classloader
[junit4:junit4] 2> 161265 T468 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 161324 T468 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 161326 T468 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 161330 T468 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 161742 T468 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 161745 T468 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 161746 T468 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 161751 T468 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 161789 T468 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 161790 T468 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1372146885570\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1372146885365/control/data\
[junit4:junit4] 2> 161790 T468 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4ce78eb9
[junit4:junit4] 2> 161790 T468 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 161790 T468 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372146885365/control/data\
[junit4:junit4] 2> 161790 T468 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1372146885365/control/data\index/
[junit4:junit4] 2> 161791 T468 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1372146885365\control\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 161791 T468 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372146885365/control/data\index
[junit4:junit4] 2> 161795 T468 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@8f2e68b lockFactory=org.apache.lucene.store.NativeFSLockFactory@3cead416),segFN=segments_1,generation=1}
[junit4:junit4] 2> 161795 T468 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 161799 T468 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 161799 T468 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 161799 T468 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 161800 T468 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 161800 T468 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 161800 T468 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 161801 T468 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 161801 T468 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 161801 T468 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 161808 T468 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 161815 T468 oass.SolrIndexSearcher.<init> Opening Searcher@6d24699c main
[junit4:junit4] 2> 161815 T468 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1372146885365\control\data\tlog
[junit4:junit4] 2> 161817 T468 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 161817 T468 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 161821 T469 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6d24699c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 161822 T468 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 161822 T468 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:64481 collection:control_collection shard:shard1
[junit4:junit4] 2> 161824 T468 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 161838 T468 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 161845 T468 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 161845 T468 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 161845 T468 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:64481/collection1/
[junit4:junit4] 2> 161845 T468 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 161846 T468 oasc.SyncStrategy.syncToMe http://127.0.0.1:64481/collection1/ has no replicas
[junit4:junit4] 2> 161846 T468 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:64481/collection1/
[junit4:junit4] 2> 161846 T468 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 162029 T466 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 162059 T465 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> 162100 T468 oasc.ZkController.register We are http://127.0.0.1:64481/collection1/ and leader is http://127.0.0.1:64481/collection1/
[junit4:junit4] 2> 162100 T468 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:64481
[junit4:junit4] 2> 162100 T468 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 162101 T468 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 162101 T468 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 162105 T468 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 162108 T443 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 162108 T443 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 162109 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 162124 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 162128 T443 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 162131 T472 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@fb43d0b name:ZooKeeperConnection Watcher:127.0.0.1:64474/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 162132 T443 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 162133 T443 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 162137 T443 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 162447 T443 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 162449 T443 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:64493
[junit4:junit4] 2> 162450 T443 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 162450 T443 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 162450 T443 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1372146888600
[junit4:junit4] 2> 162451 T443 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1372146888600\solr.xml
[junit4:junit4] 2> 162451 T443 oasc.CoreContainer.<init> New CoreContainer 1878863522
[junit4:junit4] 2> 162451 T443 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1372146888600\'
[junit4:junit4] 2> 162451 T443 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1372146888600\'
[junit4:junit4] 2> 162534 T443 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 162534 T443 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 162534 T443 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 162534 T443 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 162535 T443 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 162535 T443 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 162535 T443 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 162536 T443 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 162536 T443 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 162536 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 162542 T443 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 162542 T443 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:64474/solr
[junit4:junit4] 2> 162543 T443 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 162544 T443 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 162557 T483 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6f8c3003 name:ZooKeeperConnection Watcher:127.0.0.1:64474 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 162557 T443 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 162561 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 162569 T443 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 162572 T485 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@67d2ab6b name:ZooKeeperConnection Watcher:127.0.0.1:64474/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 162572 T443 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 162579 T443 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 163254 T466 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 163255 T466 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:64481_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64481"}
[junit4:junit4] 2> 163263 T485 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> 163264 T465 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> 163264 T472 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> 163368 T443 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:64493_
[junit4:junit4] 2> 163371 T443 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:64493_
[junit4:junit4] 2> 163377 T472 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 163377 T472 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> 163378 T485 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 163378 T485 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> 163378 T465 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 163378 T465 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> 163388 T486 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 163388 T486 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 164453 T466 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 164454 T466 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:64493_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64493"}
[junit4:junit4] 2> 164454 T466 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 164454 T466 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 164464 T485 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> 164465 T465 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> 164465 T472 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> 164962 T486 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1372146888600\collection1
[junit4:junit4] 2> 164962 T486 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 164963 T486 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 164964 T486 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 164965 T486 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1372146888600\collection1\'
[junit4:junit4] 2> 164967 T486 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1372146888600/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 164967 T486 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1372146888600/collection1/lib/README' to classloader
[junit4:junit4] 2> 165009 T486 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 165059 T486 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 165060 T486 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 165064 T486 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 165531 T486 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 165535 T486 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 165537 T486 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 165541 T486 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 165580 T486 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 165581 T486 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1372146888600\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty1\
[junit4:junit4] 2> 165581 T486 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4ce78eb9
[junit4:junit4] 2> 165581 T486 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 165581 T486 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty1\
[junit4:junit4] 2> 165581 T486 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty1\index/
[junit4:junit4] 2> 165581 T486 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1372146885365\jetty1\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 165583 T486 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty1\index
[junit4:junit4] 2> 165586 T486 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20cdcf37 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6ec80792),segFN=segments_1,generation=1}
[junit4:junit4] 2> 165586 T486 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 165590 T486 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 165590 T486 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 165591 T486 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 165591 T486 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 165591 T486 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 165591 T486 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 165591 T486 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 165593 T486 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 165593 T486 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 165600 T486 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 165606 T486 oass.SolrIndexSearcher.<init> Opening Searcher@1e52011c main
[junit4:junit4] 2> 165606 T486 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1372146885365\jetty1\tlog
[junit4:junit4] 2> 165607 T486 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 165607 T486 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 165612 T487 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1e52011c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 165614 T486 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 165614 T486 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:64493 collection:collection1 shard:shard1
[junit4:junit4] 2> 165615 T486 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 165631 T486 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 165636 T486 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 165636 T486 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 165636 T486 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:64493/collection1/
[junit4:junit4] 2> 165636 T486 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 165636 T486 oasc.SyncStrategy.syncToMe http://127.0.0.1:64493/collection1/ has no replicas
[junit4:junit4] 2> 165637 T486 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:64493/collection1/
[junit4:junit4] 2> 165637 T486 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 165650 T466 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 165663 T485 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> 165664 T465 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> 165664 T472 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> 165686 T486 oasc.ZkController.register We are http://127.0.0.1:64493/collection1/ and leader is http://127.0.0.1:64493/collection1/
[junit4:junit4] 2> 165686 T486 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:64493
[junit4:junit4] 2> 165686 T486 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 165686 T486 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 165686 T486 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 165689 T486 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 165693 T443 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 165694 T443 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 165695 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 166003 T443 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 166006 T443 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:64502
[junit4:junit4] 2> 166006 T443 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 166006 T443 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 166007 T443 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1372146892172
[junit4:junit4] 2> 166007 T443 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1372146892172\solr.xml
[junit4:junit4] 2> 166007 T443 oasc.CoreContainer.<init> New CoreContainer 324943309
[junit4:junit4] 2> 166008 T443 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1372146892172\'
[junit4:junit4] 2> 166008 T443 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1372146892172\'
[junit4:junit4] 2> 166085 T443 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 166085 T443 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 166085 T443 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 166085 T443 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 166086 T443 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 166086 T443 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 166086 T443 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 166086 T443 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 166086 T443 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 166087 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 166093 T443 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 166094 T443 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:64474/solr
[junit4:junit4] 2> 166094 T443 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 166105 T443 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 166164 T499 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@34a2d82a name:ZooKeeperConnection Watcher:127.0.0.1:64474 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 166164 T443 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 166170 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 166179 T443 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 166183 T501 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@22389da7 name:ZooKeeperConnection Watcher:127.0.0.1:64474/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 166183 T443 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 166192 T443 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 166831 T466 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 166832 T466 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:64493_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64493"}
[junit4:junit4] 2> 166846 T501 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> 166847 T485 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> 166848 T465 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> 166849 T472 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> 166942 T443 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:64502_
[junit4:junit4] 2> 166945 T443 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:64502_
[junit4:junit4] 2> 166947 T501 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> 166948 T472 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 166949 T472 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> 166950 T465 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 166950 T465 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> 166950 T485 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 166951 T485 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> 166952 T501 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 166961 T502 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 166961 T502 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 167927 T466 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 167928 T466 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:64502_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64502"}
[junit4:junit4] 2> 167928 T466 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 167928 T466 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 167938 T485 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> 167938 T501 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> 167940 T465 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> 167939 T472 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> 168377 T502 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1372146892172\collection1
[junit4:junit4] 2> 168377 T502 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 168379 T502 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 168379 T502 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 168383 T502 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1372146892172\collection1\'
[junit4:junit4] 2> 168386 T502 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1372146892172/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 168387 T502 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1372146892172/collection1/lib/README' to classloader
[junit4:junit4] 2> 168430 T502 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 168472 T502 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 168474 T502 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 168477 T502 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 168848 T502 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 168850 T502 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 168852 T502 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 168855 T502 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 168886 T502 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 168886 T502 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1372146892172\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty2\
[junit4:junit4] 2> 168887 T502 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4ce78eb9
[junit4:junit4] 2> 168887 T502 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 168888 T502 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty2\
[junit4:junit4] 2> 168888 T502 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty2\index/
[junit4:junit4] 2> 168888 T502 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1372146885365\jetty2\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 168888 T502 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty2\index
[junit4:junit4] 2> 168892 T502 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1435e7c5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7682402c),segFN=segments_1,generation=1}
[junit4:junit4] 2> 168892 T502 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 168895 T502 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 168895 T502 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 168895 T502 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 168895 T502 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 168896 T502 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 168896 T502 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 168896 T502 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 168897 T502 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 168897 T502 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 168904 T502 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 168908 T502 oass.SolrIndexSearcher.<init> Opening Searcher@39670f81 main
[junit4:junit4] 2> 168908 T502 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1372146885365\jetty2\tlog
[junit4:junit4] 2> 168910 T502 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 168910 T502 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 168914 T503 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@39670f81 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 168915 T502 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 168915 T502 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:64502 collection:collection1 shard:shard2
[junit4:junit4] 2> 168917 T502 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 168933 T502 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 168942 T502 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 168942 T502 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 168942 T502 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:64502/collection1/
[junit4:junit4] 2> 168942 T502 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 168942 T502 oasc.SyncStrategy.syncToMe http://127.0.0.1:64502/collection1/ has no replicas
[junit4:junit4] 2> 168942 T502 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:64502/collection1/
[junit4:junit4] 2> 168942 T502 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 169006 T466 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 169030 T472 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> 169031 T465 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> 169031 T501 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> 169031 T485 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> 169058 T502 oasc.ZkController.register We are http://127.0.0.1:64502/collection1/ and leader is http://127.0.0.1:64502/collection1/
[junit4:junit4] 2> 169058 T502 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:64502
[junit4:junit4] 2> 169058 T502 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 169058 T502 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 169058 T502 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 169061 T502 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 169062 T443 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 169062 T443 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 169063 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 169358 T443 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 169363 T443 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:64511
[junit4:junit4] 2> 169363 T443 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 169363 T443 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 169364 T443 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1372146895534
[junit4:junit4] 2> 169364 T443 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1372146895534\solr.xml
[junit4:junit4] 2> 169364 T443 oasc.CoreContainer.<init> New CoreContainer 6648780
[junit4:junit4] 2> 169365 T443 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1372146895534\'
[junit4:junit4] 2> 169366 T443 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1372146895534\'
[junit4:junit4] 2> 169446 T443 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 169446 T443 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 169446 T443 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 169446 T443 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 169447 T443 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 169447 T443 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 169448 T443 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 169448 T443 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 169448 T443 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 169448 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 169455 T443 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 169456 T443 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:64474/solr
[junit4:junit4] 2> 169456 T443 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 169457 T443 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 169468 T515 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@47596c17 name:ZooKeeperConnection Watcher:127.0.0.1:64474 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 169468 T443 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 169471 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 169476 T443 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 169479 T517 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19d4a8bf name:ZooKeeperConnection Watcher:127.0.0.1:64474/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 169479 T443 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 169484 T443 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 170111 T466 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 170113 T466 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:64502_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64502"}
[junit4:junit4] 2> 170123 T472 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> 170123 T501 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> 170124 T485 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> 170123 T517 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> 170124 T465 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> 170195 T443 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:64511_
[junit4:junit4] 2> 170198 T443 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:64511_
[junit4:junit4] 2> 170205 T501 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> 170214 T517 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 170214 T517 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> 170214 T485 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 170214 T485 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> 170216 T465 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 170216 T465 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> 170218 T472 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 170218 T472 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> 170220 T501 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 170227 T518 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 170227 T518 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 171191 T466 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 171192 T466 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:64511_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64511"}
[junit4:junit4] 2> 171192 T466 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 171192 T466 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 171203 T472 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> 171203 T517 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> 171204 T501 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> 171204 T465 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> 171204 T485 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> 171644 T518 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1372146895534\collection1
[junit4:junit4] 2> 171644 T518 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 171646 T518 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 171646 T518 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 171650 T518 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1372146895534\collection1\'
[junit4:junit4] 2> 171653 T518 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1372146895534/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 171654 T518 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1372146895534/collection1/lib/README' to classloader
[junit4:junit4] 2> 171700 T518 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 171746 T518 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 171748 T518 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 171751 T518 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 172154 T518 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 172155 T518 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 172157 T518 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 172162 T518 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 172193 T518 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 172193 T518 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1372146895534\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty3\
[junit4:junit4] 2> 172193 T518 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4ce78eb9
[junit4:junit4] 2> 172194 T518 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 172194 T518 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty3\
[junit4:junit4] 2> 172194 T518 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty3\index/
[junit4:junit4] 2> 172195 T518 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1372146885365\jetty3\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 172195 T518 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty3\index
[junit4:junit4] 2> 172198 T518 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e000dd7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@769d509b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 172199 T518 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 172201 T518 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 172201 T518 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 172202 T518 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 172203 T518 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 172204 T518 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 172204 T518 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 172204 T518 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 172204 T518 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 172205 T518 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 172213 T518 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 172217 T518 oass.SolrIndexSearcher.<init> Opening Searcher@2286a7e main
[junit4:junit4] 2> 172218 T518 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1372146885365\jetty3\tlog
[junit4:junit4] 2> 172219 T518 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 172219 T518 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 172223 T519 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2286a7e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 172224 T518 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 172224 T518 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:64511 collection:collection1 shard:shard1
[junit4:junit4] 2> 172233 T518 oasc.ZkController.register We are http://127.0.0.1:64511/collection1/ and leader is http://127.0.0.1:64493/collection1/
[junit4:junit4] 2> 172233 T518 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:64511
[junit4:junit4] 2> 172233 T518 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 172233 T518 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C62 name=collection1 org.apache.solr.core.SolrCore@38cf728d url=http://127.0.0.1:64511/collection1 node=127.0.0.1:64511_ C62_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:64511_, base_url=http://127.0.0.1:64511}
[junit4:junit4] 2> 172235 T520 C62 P64511 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 172235 T520 C62 P64511 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 172236 T520 C62 P64511 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 172236 T520 C62 P64511 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 172236 T518 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 172238 T520 C62 P64511 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 172239 T443 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 172239 T443 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 172239 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 172255 T475 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 172276 T466 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 172277 T466 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:64511_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64511"}
[junit4:junit4] 2> 172286 T517 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> 172286 T501 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> 172286 T485 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> 172287 T465 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> 172286 T472 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> 172553 T443 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 172558 T443 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:64521
[junit4:junit4] 2> 172558 T443 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 172558 T443 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 172559 T443 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1372146898707
[junit4:junit4] 2> 172559 T443 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1372146898707\solr.xml
[junit4:junit4] 2> 172559 T443 oasc.CoreContainer.<init> New CoreContainer 1886784671
[junit4:junit4] 2> 172561 T443 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1372146898707\'
[junit4:junit4] 2> 172561 T443 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1372146898707\'
[junit4:junit4] 2> 172657 T443 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 172657 T443 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 172658 T443 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 172658 T443 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 172659 T443 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 172659 T443 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 172659 T443 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 172659 T443 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 172660 T443 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 172660 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 172668 T443 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 172668 T443 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:64474/solr
[junit4:junit4] 2> 172668 T443 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 172670 T443 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 172680 T532 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2111bc5f name:ZooKeeperConnection Watcher:127.0.0.1:64474 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 172681 T443 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 172684 T445 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f7a53e2fd000b, 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:724)
[junit4:junit4] 2>
[junit4:junit4] 2> 172684 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 172690 T443 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 172694 T534 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5bbf1aae name:ZooKeeperConnection Watcher:127.0.0.1:64474/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 172694 T443 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 172702 T443 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 172962 T475 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 172962 T475 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:64511_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=707
[junit4:junit4] 2> 173415 T443 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:64521_
[junit4:junit4] 2> 173422 T443 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:64521_
[junit4:junit4] 2> 173430 T501 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> 173434 T517 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 173435 T517 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> 173435 T472 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 173435 T465 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 173435 T534 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 173435 T472 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> 173435 T485 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 173436 T485 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> 173435 T465 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> 173439 T501 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 173444 T535 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 173444 T535 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> ASYNC NEW_CORE C63 name=collection1 org.apache.solr.core.SolrCore@38cf728d url=http://127.0.0.1:64511/collection1 node=127.0.0.1:64511_ C63_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:64511_, base_url=http://127.0.0.1:64511}
[junit4:junit4] 2> 174449 T520 C63 P64511 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:64493/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 174450 T520 C63 P64511 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:64511 START replicas=[http://127.0.0.1:64493/collection1/] nUpdates=100
[junit4:junit4] 2> 174453 T520 C63 P64511 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 174462 T520 C63 P64511 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 174462 T520 C63 P64511 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 174463 T520 C63 P64511 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 174464 T520 C63 P64511 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 174464 T520 C63 P64511 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:64493/collection1/. core=collection1
[junit4:junit4] 2> 174465 T520 C63 P64511 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C64 name=collection1 org.apache.solr.core.SolrCore@551e4cea url=http://127.0.0.1:64493/collection1 node=127.0.0.1:64493_ C64_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:64493_, base_url=http://127.0.0.1:64493, leader=true}
[junit4:junit4] 2> 174478 T476 C64 P64493 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 174478 T475 C64 P64493 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 174482 T476 C64 P64493 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20cdcf37 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6ec80792),segFN=segments_1,generation=1}
[junit4:junit4] 2> 174483 T476 C64 P64493 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 174483 T476 C64 P64493 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20cdcf37 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6ec80792),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20cdcf37 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6ec80792),segFN=segments_2,generation=2}
[junit4:junit4] 2> 174483 T476 C64 P64493 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 174484 T476 C64 P64493 oass.SolrIndexSearcher.<init> Opening Searcher@483eaee1 realtime
[junit4:junit4] 2> 174484 T476 C64 P64493 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 174484 T476 C64 P64493 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> 174485 T520 C63 P64511 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 174485 T520 C63 P64511 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 174487 T481 C64 P64493 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 174488 T481 C64 P64493 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 174488 T520 C63 P64511 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 174488 T520 C63 P64511 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 174489 T520 C63 P64511 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 174491 T479 C64 P64493 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 174491 T520 C63 P64511 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 174493 T520 C63 P64511 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty3\index.20130624215500956
[junit4:junit4] 2> 174493 T520 C63 P64511 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@345c4417 lockFactory=org.apache.lucene.store.NativeFSLockFactory@53f6812e) fullCopy=false
[junit4:junit4] 2> 174495 T477 C64 P64493 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 174497 T520 C63 P64511 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 174499 T520 C63 P64511 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 174499 T520 C63 P64511 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 174499 T466 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 174500 T466 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:64521_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64521"}
[junit4:junit4] 2> 174500 T466 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 174500 T466 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 174503 T520 C63 P64511 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e000dd7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@769d509b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e000dd7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@769d509b),segFN=segments_2,generation=2}
[junit4:junit4] 2> 174503 T520 C63 P64511 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 174503 T520 C63 P64511 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 174503 T520 C63 P64511 oass.SolrIndexSearcher.<init> Opening Searcher@74d93ebb main
[junit4:junit4] 2> 174504 T519 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@74d93ebb main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 174505 T520 C63 P64511 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty3\index.20130624215500956 [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty3\index.20130624215500956;done=true>>]
[junit4:junit4] 2> 174505 T520 C63 P64511 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty3\index.20130624215500956
[junit4:junit4] 2> 174505 T520 C63 P64511 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty3\index.20130624215500956
[junit4:junit4] 2> 174506 T520 C63 P64511 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 174506 T520 C63 P64511 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 174506 T520 C63 P64511 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 174506 T520 C63 P64511 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 174507 T520 C63 P64511 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 174510 T466 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:64511_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64511"}
[junit4:junit4] 2> 174517 T534 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> 174517 T472 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> 174518 T517 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> 174518 T501 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> 174518 T485 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> 174519 T465 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> 174980 T535 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1372146898707\collection1
[junit4:junit4] 2> 174980 T535 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 174981 T535 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 174981 T535 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 174983 T535 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1372146898707\collection1\'
[junit4:junit4] 2> 174985 T535 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1372146898707/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 174986 T535 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1372146898707/collection1/lib/README' to classloader
[junit4:junit4] 2> 175024 T535 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 175070 T535 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 175073 T535 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 175077 T535 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 175516 T535 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 175518 T535 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 175536 T535 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 175544 T535 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 175579 T535 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 175580 T535 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1372146898707\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty4\
[junit4:junit4] 2> 175580 T535 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@4ce78eb9
[junit4:junit4] 2> 175580 T535 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 175581 T535 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty4\
[junit4:junit4] 2> 175581 T535 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty4\index/
[junit4:junit4] 2> 175581 T535 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1372146885365\jetty4\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 175582 T535 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty4\index
[junit4:junit4] 2> 175584 T535 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@138d7b91 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65605543),segFN=segments_1,generation=1}
[junit4:junit4] 2> 175584 T535 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 175587 T535 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 175588 T535 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 175588 T535 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 175589 T535 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 175591 T535 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 175591 T535 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 175593 T535 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 175593 T535 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 175594 T535 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 175602 T535 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 175607 T535 oass.SolrIndexSearcher.<init> Opening Searcher@42a46d79 main
[junit4:junit4] 2> 175608 T535 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1372146885365\jetty4\tlog
[junit4:junit4] 2> 175609 T535 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 175609 T535 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 175615 T535 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 175615 T535 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:64521 collection:collection1 shard:shard2
[junit4:junit4] 2> 175616 T538 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@42a46d79 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 175635 T535 oasc.ZkController.register We are http://127.0.0.1:64521/collection1/ and leader is http://127.0.0.1:64502/collection1/
[junit4:junit4] 2> 175635 T535 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:64521
[junit4:junit4] 2> 175635 T535 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 175636 T535 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> 175637 T535 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 175638 T443 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 175638 T443 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 175639 T443 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 175648 T443 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 175649 T443 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 175650 T443 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 175650 T443 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C65 name=collection1 org.apache.solr.core.SolrCore@333cf5e3 url=http://127.0.0.1:64521/collection1 node=127.0.0.1:64521_ C65_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:64521_, base_url=http://127.0.0.1:64521}
[junit4:junit4] 2> 175651 T539 C65 P64521 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 175652 T539 C65 P64521 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 175652 T539 C65 P64521 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 175652 T539 C65 P64521 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 175655 T539 C65 P64521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 175661 T496 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 175696 T466 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 175697 T466 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:64521_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64521"}
[junit4:junit4] 2> 175780 T534 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> 175781 T517 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> 175781 T472 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> 175782 T465 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> 175782 T485 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> 175782 T501 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> 176430 T443 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 176440 T496 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 176440 T496 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:64521_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=779
[junit4:junit4] 2> 177211 T443 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 177991 T443 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C65_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:64521_, base_url=http://127.0.0.1:64521}
[junit4:junit4] 2> 177996 T539 C65 P64521 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:64502/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 177996 T539 C65 P64521 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:64521 START replicas=[http://127.0.0.1:64502/collection1/] nUpdates=100
[junit4:junit4] 2> 177997 T539 C65 P64521 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 177998 T539 C65 P64521 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 177998 T539 C65 P64521 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 177998 T539 C65 P64521 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 177999 T539 C65 P64521 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 177999 T539 C65 P64521 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:64502/collection1/. core=collection1
[junit4:junit4] 2> 177999 T539 C65 P64521 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C66 name=collection1 org.apache.solr.core.SolrCore@33ed918d url=http://127.0.0.1:64502/collection1 node=127.0.0.1:64502_ C66_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:64502_, base_url=http://127.0.0.1:64502, leader=true}
[junit4:junit4] 2> 178023 T497 C66 P64502 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> 178024 T497 C66 P64502 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 178027 T497 C66 P64502 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1435e7c5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7682402c),segFN=segments_1,generation=1}
[junit4:junit4] 2> 178028 T497 C66 P64502 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 178028 T497 C66 P64502 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1435e7c5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7682402c),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1435e7c5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7682402c),segFN=segments_2,generation=2}
[junit4:junit4] 2> 178028 T497 C66 P64502 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 178029 T497 C66 P64502 oass.SolrIndexSearcher.<init> Opening Searcher@34a5c866 realtime
[junit4:junit4] 2> 178029 T497 C66 P64502 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 178029 T497 C66 P64502 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> 178029 T539 C65 P64521 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 178030 T539 C65 P64521 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 178032 T492 C66 P64502 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 178032 T492 C66 P64502 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 178032 T539 C65 P64521 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 178033 T539 C65 P64521 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 178033 T539 C65 P64521 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 178035 T494 C66 P64502 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> 178035 T539 C65 P64521 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 178036 T539 C65 P64521 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty4\index.20130624215504499
[junit4:junit4] 2> 178036 T539 C65 P64521 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@698c752a lockFactory=org.apache.lucene.store.NativeFSLockFactory@278e55d1) fullCopy=false
[junit4:junit4] 2> 178039 T495 C66 P64502 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 178041 T539 C65 P64521 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 178042 T539 C65 P64521 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 178042 T539 C65 P64521 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 178045 T539 C65 P64521 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@138d7b91 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65605543),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@138d7b91 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65605543),segFN=segments_2,generation=2}
[junit4:junit4] 2> 178045 T539 C65 P64521 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 178045 T539 C65 P64521 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 178045 T539 C65 P64521 oass.SolrIndexSearcher.<init> Opening Searcher@3e47b835 main
[junit4:junit4] 2> 178047 T538 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3e47b835 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 178047 T539 C65 P64521 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty4\index.20130624215504499 [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty4\index.20130624215504499;done=true>>]
[junit4:junit4] 2> 178047 T539 C65 P64521 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty4\index.20130624215504499
[junit4:junit4] 2> 178047 T539 C65 P64521 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty4\index.20130624215504499
[junit4:junit4] 2> 178048 T539 C65 P64521 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 178048 T539 C65 P64521 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 178048 T539 C65 P64521 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 178048 T539 C65 P64521 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 178056 T539 C65 P64521 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 178130 T466 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 178131 T466 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:64521_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:64521"}
[junit4:junit4] 2> 178140 T534 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> 178140 T472 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> 178141 T517 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> 178142 T501 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> 178142 T485 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> 178143 T465 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> 178772 T443 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 178774 T443 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C67 name=collection1 org.apache.solr.core.SolrCore@68e68e23 url=http://127.0.0.1:64481/collection1 node=127.0.0.1:64481_ C67_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:64481_, base_url=http://127.0.0.1:64481, leader=true}
[junit4:junit4] 2> 178784 T458 C67 P64481 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 178789 T458 C67 P64481 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@8f2e68b lockFactory=org.apache.lucene.store.NativeFSLockFactory@3cead416),segFN=segments_1,generation=1}
[junit4:junit4] 2> 178790 T458 C67 P64481 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 178790 T458 C67 P64481 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@8f2e68b lockFactory=org.apache.lucene.store.NativeFSLockFactory@3cead416),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@8f2e68b lockFactory=org.apache.lucene.store.NativeFSLockFactory@3cead416),segFN=segments_2,generation=2}
[junit4:junit4] 2> 178791 T458 C67 P64481 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 178791 T458 C67 P64481 oass.SolrIndexSearcher.<init> Opening Searcher@30e5dde1 main
[junit4:junit4] 2> 178791 T458 C67 P64481 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 178792 T469 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@30e5dde1 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 178793 T458 C67 P64481 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 C68 name=collection1 org.apache.solr.core.SolrCore@551e4cea url=http://127.0.0.1:64493/collection1 node=127.0.0.1:64493_ C68_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:64493_, base_url=http://127.0.0.1:64493, leader=true}
[junit4:junit4] 2> 178799 T476 C68 P64493 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:64493/collection1/, StdNode: http://127.0.0.1:64511/collection1/, StdNode: http://127.0.0.1:64502/collection1/, StdNode: http://127.0.0.1:64521/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 178803 T478 C68 P64493 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C65_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:64521_, base_url=http://127.0.0.1:64521}
[junit4:junit4] 2> 178812 T529 C65 P64521 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C69 name=collection1 org.apache.solr.core.SolrCore@38cf728d url=http://127.0.0.1:64511/collection1 node=127.0.0.1:64511_ C69_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:64511_, base_url=http://127.0.0.1:64511}
[junit4:junit4] 2> 178811 T511 C69 P64511 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 178813 T497 C66 P64502 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 178816 T529 C65 P64521 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@138d7b91 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65605543),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@138d7b91 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65605543),segFN=segments_3,generation=3}
[junit4:junit4] 2> 178816 T529 C65 P64521 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 178815 T478 C68 P64493 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20cdcf37 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6ec80792),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@20cdcf37 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6ec80792),segFN=segments_3,generation=3}
[junit4:junit4] 2> 178817 T478 C68 P64493 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 178816 T511 C69 P64511 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e000dd7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@769d509b),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@e000dd7 lockFactory=org.apache.lucene.store.NativeFSLockFactory@769d509b),segFN=segments_3,generation=3}
[junit4:junit4] 2> 178818 T511 C69 P64511 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 178816 T497 C66 P64502 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1435e7c5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7682402c),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1435e7c5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@7682402c),segFN=segments_3,generation=3}
[junit4:junit4] 2> 178819 T497 C66 P64502 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 178819 T511 C69 P64511 oass.SolrIndexSearcher.<init> Opening Searcher@413306f7 main
[junit4:junit4] 2> 178818 T478 C68 P64493 oass.SolrIndexSearcher.<init> Opening Searcher@34150c25 main
[junit4:junit4] 2> 178819 T478 C68 P64493 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 178817 T529 C65 P64521 oass.SolrIndexSearcher.<init> Opening Searcher@4404df37 main
[junit4:junit4] 2> 178821 T529 C65 P64521 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 178821 T487 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@34150c25 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 178821 T519 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@413306f7 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 178819 T511 C69 P64511 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 178822 T511 C69 P64511 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 11
[junit4:junit4] 2> 178819 T497 C66 P64502 oass.SolrIndexSearcher.<init> Opening Searcher@3bab04bb main
[junit4:junit4] 2> 178823 T497 C66 P64502 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 178822 T478 C68 P64493 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 19
[junit4:junit4] 2> 178824 T503 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3bab04bb main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 178822 T538 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4404df37 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 178825 T497 C66 P64502 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 12
[junit4:junit4] 2> 178825 T529 C65 P64521 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 14
[junit4:junit4] 2> 178826 T476 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 28
[junit4:junit4] 2> 178827 T443 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 178834 T481 C68 P64493 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> 178838 T513 C69 P64511 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> 178841 T492 C66 P64502 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> 178844 T530 C65 P64521 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> 180405 T455 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438800315013922816)} 0 2
[junit4:junit4] 2> 180417 T510 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438800315019165696&update.from=http://127.0.0.1:64493/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438800315019165696)} 0 3
[junit4:junit4] 2> 180421 T528 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438800315024408576&update.from=http://127.0.0.1:64502/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438800315024408576)} 0 2
[junit4:junit4] 2> 180421 T496 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438800315024408576)} 0 8
[junit4:junit4] 2> 180422 T478 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438800315019165696)} 0 14
[junit4:junit4] 2> 180427 T457 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1438800315036991488)]} 0 2
[junit4:junit4] 2> 180436 T529 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1438800315044331520)]} 0 2
[junit4:junit4] 2> 180437 T493 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!0 (1438800315044331520)]} 0 6
[junit4:junit4] 2> 180438 T476 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0]} 0 8
[junit4:junit4] 2> 180441 T456 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1438800315052720128)]} 0 1
[junit4:junit4] 2> 180452 T512 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1438800315059011584)]} 0 2
[junit4:junit4] 2> 180453 T481 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!1 (1438800315059011584)]} 0 7
[junit4:junit4] 2> 180453 T497 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1]} 0 9
[junit4:junit4] 2> 180458 T459 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1438800315070545920)]} 0 1
[junit4:junit4] 2> 180468 T511 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1438800315077885952)]} 0 0
[junit4:junit4] 2> 180470 T479 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!2 (1438800315077885952)]} 0 6
[junit4:junit4] 2> 180471 T492 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2]} 0 10
[junit4:junit4] 2> 180475 T460 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1438800315088371712)]} 0 1
[junit4:junit4] 2> 180484 T530 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1438800315092566016)]} 0 2
[junit4:junit4] 2> 180485 T494 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1438800315092566016)]} 0 7
[junit4:junit4] 2> 180490 T455 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1438800315104100352)]} 0 1
[junit4:junit4] 2> 180503 T525 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1438800315115634688)]} 0 0
[junit4:junit4] 2> 180506 T495 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!4 (1438800315115634688)]} 0 6
[junit4:junit4] 2> 180507 T477 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4]} 0 13
[junit4:junit4] 2> 180510 T457 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1438800315126120448)]} 0 0
[junit4:junit4] 2> 180518 T526 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1438800315132411904)]} 0 1
[junit4:junit4] 2> 180518 T493 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!5 (1438800315132411904)]} 0 2
[junit4:junit4] 2> 180519 T475 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5]} 0 6
[junit4:junit4] 2> 180522 T458 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1438800315138703360)]} 0 1
[junit4:junit4] 2> 180528 T513 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1438800315141849088)]} 0 1
[junit4:junit4] 2> 180529 T478 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1438800315141849088)]} 0 4
[junit4:junit4] 2> 180532 T456 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1438800315149189120)]} 0 1
[junit4:junit4] 2> 180539 T509 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1438800315153383424)]} 0 1
[junit4:junit4] 2> 180540 T476 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!7 (1438800315153383424)]} 0 4
[junit4:junit4] 2> 180540 T497 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7]} 0 6
[junit4:junit4] 2> 180544 T459 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1438800315161772032)]} 0 0
[junit4:junit4] 2> 180552 T510 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1438800315164917760)]} 0 1
[junit4:junit4] 2> 180553 T481 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1438800315164917760)]} 0 6
[junit4:junit4] 2> 180557 T460 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1438800315174354944)]} 0 1
[junit4:junit4] 2> 180566 T512 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1438800315181694976)]} 0 0
[junit4:junit4] 2> 180567 T479 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!9 (1438800315181694976)]} 0 4
[junit4:junit4] 2> 180569 T492 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9]} 0 9
[junit4:junit4] 2> 180573 T455 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1438800315191132160)]} 0 1
[junit4:junit4] 2> 180604 T511 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1438800315221540864)]} 0 0
[junit4:junit4] 2> 180605 T477 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1438800315221540864)]} 0 4
[junit4:junit4] 2> 180608 T457 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1438800315228880896)]} 0 0
[junit4:junit4] 2> 180615 T527 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1438800315233075200)]} 0 1
[junit4:junit4] 2> 180617 T494 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!11 (1438800315233075200)]} 0 5
[junit4:junit4] 2> 180617 T475 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11]} 0 7
[junit4:junit4] 2> 180620 T458 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1438800315241463808)]} 0 0
[junit4:junit4] 2> 180628 T528 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1438800315247755264)]} 0 1
[junit4:junit4] 2> 180629 T495 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!12 (1438800315247755264)]} 0 4
[junit4:junit4] 2> 180630 T478 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12]} 0 7
[junit4:junit4] 2> 180633 T456 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1438800315255095296)]} 0 0
[junit4:junit4] 2> 180639 T508 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1438800315258241024)]} 0 0
[junit4:junit4] 2> 180640 T476 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1438800315258241024)]} 0 4
[junit4:junit4] 2> 180643 T459 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1438800315265581056)]} 0 1
[junit4:junit4] 2> 180650 T529 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1438800315269775360)]} 0 1
[junit4:junit4] 2> 180652 T496 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1438800315269775360)]} 0 6
[junit4:junit4] 2> 180657 T460 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1438800315279212544)]} 0 1
[junit4:junit4] 2> 180664 T513 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1438800315283406848)]} 0 1
[junit4:junit4] 2> 180665 T481 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1438800315283406848)]} 0 5
[junit4:junit4] 2> 180670 T455 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1438800315292844032)]} 0 1
[junit4:junit4] 2> 180677 T509 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1438800315297038336)]} 0 1
[junit4:junit4] 2> 180678 T479 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1438800315297038336)]} 0 5
[junit4:junit4] 2> 180681 T457 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1438800315305426944)]} 0 0
[junit4:junit4] 2> 180690 T530 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1438800315310669824)]} 0 1
[junit4:junit4] 2> 180690 T493 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1438800315310669824)]} 0 4
[junit4:junit4] 2> 180695 T458 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1438800315319058432)]} 0 1
[junit4:junit4] 2> 180706 T510 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1438800315326398464)]} 0 1
[junit4:junit4] 2> 180708 T477 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!18 (1438800315326398464)]} 0 7
[junit4:junit4] 2> 180709 T497 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18]} 0 11
[junit4:junit4] 2> 180713 T456 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1438800315337932800)]} 0 1
[junit4:junit4] 2> 180724 T512 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1438800315346321408)]} 0 1
[junit4:junit4] 2> 180725 T475 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!19 (1438800315346321408)]} 0 5
[junit4:junit4] 2> 180726 T492 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19]} 0 9
[junit4:junit4] 2> 180731 T459 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1438800315356807168)]} 0 2
[junit4:junit4] 2> 180739 T525 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1438800315361001472)]} 0 1
[junit4:junit4] 2> 180742 T494 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1438800315361001472)]} 0 8
[junit4:junit4] 2> 180746 T460 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1438800315373584384)]} 0 2
[junit4:junit4] 2> 180758 T511 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1438800315377778688)]} 0 1
[junit4:junit4] 2> 180759 T478 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1438800315377778688)]} 0 9
[junit4:junit4] 2> 180762 T455 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1438800315389313024)]} 0 1
[junit4:junit4] 2> 180766 T508 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1438800315391410176)]} 0 0
[junit4:junit4] 2> 180766 T476 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1438800315391410176)]} 0 3
[junit4:junit4] 2> 180769 T457 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1438800315397701632)]} 0 0
[junit4:junit4] 2> 180774 T526 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1438800315399798784)]} 0 1
[junit4:junit4] 2> 180775 T495 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1438800315399798784)]} 0 4
[junit4:junit4] 2> 180778 T458 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1438800315407138816)]} 0 0
[junit4:junit4] 2> 180786 T527 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1438800315413430272)]} 0 1
[junit4:junit4] 2> 180788 T496 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!24 (1438800315413430272)]} 0 5
[junit4:junit4] 2> 180789 T481 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24]} 0 8
[junit4:junit4] 2> 180794 T456 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1438800315422867456)]} 0 1
[junit4:junit4] 2> 180803 T513 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1438800315430207488)]} 0 0
[junit4:junit4] 2> 180803 T479 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!25 (1438800315430207488)]} 0 4
[junit4:junit4] 2> 180805 T493 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25]} 0 8
[junit4:junit4] 2> 180810 T459 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1438800315440693248)]} 0 0
[junit4:junit4] 2> 180820 T528 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1438800315449081856)]} 0 0
[junit4:junit4] 2> 180822 T497 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!26 (1438800315449081856)]} 0 5
[junit4:junit4] 2> 180822 T475 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26]} 0 8
[junit4:junit4] 2> 180827 T460 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1438800315457470464)]} 0 1
[junit4:junit4] 2> 180836 T509 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1438800315463761920)]} 0 0
[junit4:junit4] 2> 180837 T478 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!27 (1438800315463761920)]} 0 5
[junit4:junit4] 2> 180838 T492 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27]} 0 8
[junit4:junit4] 2> 180842 T455 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1438800315473199104)]} 0 1
[junit4:junit4] 2> 180849 T510 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1438800315477393408)]} 0 1
[junit4:junit4] 2> 180851 T476 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1438800315477393408)]} 0 6
[junit4:junit4] 2> 180855 T458 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1438800315486830592)]} 0 1
[junit4:junit4] 2> 180865 T530 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1438800315495219200)]} 0 1
[junit4:junit4] 2> 180865 T494 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!29 (1438800315495219200)]} 0 4
[junit4:junit4] 2> 180866 T481 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29]} 0 7
[junit4:junit4] 2> 180869 T456 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1438800315502559232)]} 0 1
[junit4:junit4] 2> 180875 T525 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1438800315506753536)]} 0 0
[junit4:junit4] 2> 180876 T495 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!30 (1438800315506753536)]} 0 3
[junit4:junit4] 2> 180877 T477 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30]} 0 6
[junit4:junit4] 2> 180880 T459 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1438800315514093568)]} 0 1
[junit4:junit4] 2> 180888 T526 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1438800315519336448)]} 0 1
[junit4:junit4] 2> 180888 T496 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!31 (1438800315519336448)]} 0 3
[junit4:junit4] 2> 180889 T479 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31]} 0 7
[junit4:junit4] 2> 180892 T460 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1438800315526676480)]} 0 1
[junit4:junit4] 2> 180895 T512 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1438800315527725056)]} 0 0
[junit4:junit4] 2> 180896 T475 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1438800315527725056)]} 0 3
[junit4:junit4] 2> 180899 T457 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1438800315534016512)]} 0 1
[junit4:junit4] 2> 180913 T511 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1438800315545550848)]} 0 2
[junit4:junit4] 2> 180914 T478 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!33 (1438800315545550848)]} 0 5
[junit4:junit4] 2> 180915 T493 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33]} 0 8
[junit4:junit4] 2> 180918 T455 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1438800315553939456)]} 0 1
[junit4:junit4] 2> 180928 T508 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1438800315560230912)]} 0 1
[junit4:junit4] 2> 180929 T476 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!34 (1438800315560230912)]} 0 5
[junit4:junit4] 2> 180930 T492 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34]} 0 8
[junit4:junit4] 2> 180934 T458 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1438800315569668096)]} 0 1
[junit4:junit4] 2> 180942 T509 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1438800315574910976)]} 0 1
[junit4:junit4] 2> 180942 T481 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1438800315574910976)]} 0 4
[junit4:junit4] 2> 180947 T456 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1438800315583299584)]} 0 1
[junit4:junit4] 2> 180957 T510 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1438800315588542464)]} 0 1
[junit4:junit4] 2> 180958 T477 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1438800315588542464)]} 0 9
[junit4:junit4] 2> 180961 T459 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1438800315599028224)]} 0 0
[junit4:junit4] 2> 180968 T527 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1438800315604271104)]} 0 0
[junit4:junit4] 2> 180970 T494 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!37 (1438800315604271104)]} 0 4
[junit4:junit4] 2> 180970 T479 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37]} 0 6
[junit4:junit4] 2> 180973 T460 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1438800315610562560)]} 0 1
[junit4:junit4] 2> 180979 T529 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1438800315614756864)]} 0 0
[junit4:junit4] 2> 180980 T495 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!38 (1438800315614756864)]} 0 4
[junit4:junit4] 2> 180980 T475 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38]} 0 6
[junit4:junit4] 2> 180984 T457 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1438800315622096896)]} 0 1
[junit4:junit4] 2> 180987 T512 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1438800315625242624)]} 0 0
[junit4:junit4] 2> 180988 T478 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1438800315625242624)]} 0 2
[junit4:junit4] 2> 180992 T455 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1438800315630485504)]} 0 1
[junit4:junit4] 2> 180996 T528 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1438800315633631232)]} 0 0
[junit4:junit4] 2> 180997 T496 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1438800315633631232)]} 0 3
[junit4:junit4] 2> 181000 T458 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41 (1438800315638874112)]} 0 1
[junit4:junit4] 2> 181009 T511 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1438800315644116992)]} 0 0
[junit4:junit4] 2> 181011 T476 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!41 (1438800315644116992)]} 0 7
[junit4:junit4] 2> 181012 T497 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41]} 0 10
[junit4:junit4] 2> 181016 T456 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1438800315655651328)]} 0 1
[junit4:junit4] 2> 181022 T508 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1438800315659845632)]} 0 1
[junit4:junit4] 2> 181023 T481 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1438800315659845632)]} 0 4
[junit4:junit4] 2> 181026 T459 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1438800315666137088)]} 0 1
[junit4:junit4] 2> 181031 T530 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1438800315670331392)]} 0 0
[junit4:junit4] 2> 181032 T493 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1438800315670331392)]} 0 4
[junit4:junit4] 2> 181037 T460 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1438800315678720000)]} 0 0
[junit4:junit4] 2> 181045 T513 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1438800315683962880)]} 0 1
[junit4:junit4] 2> 181046 T477 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!44 (1438800315683962880)]} 0 4
[junit4:junit4] 2> 181046 T492 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44]} 0 6
[junit4:junit4] 2> 181049 T457 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1438800315690254336)]} 0 1
[junit4:junit4] 2> 181056 T509 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1438800315695497216)]} 0 1
[junit4:junit4] 2> 181056 T479 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!45 (1438800315695497216)]} 0 3
[junit4:junit4] 2> 181057 T494 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45]} 0 7
[junit4:junit4] 2> 181060 T455 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1438800315701788672)]} 0 1
[junit4:junit4] 2> 181066 T525 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1438800315705982976)]} 0 1
[junit4:junit4] 2> 181066 T495 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1438800315705982976)]} 0 3
[junit4:junit4] 2> 181069 T458 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1438800315712274432)]} 0 0
[junit4:junit4] 2> 181077 T510 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1438800315717517312)]} 0 1
[junit4:junit4] 2> 181078 T475 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1438800315717517312)]} 0 5
[junit4:junit4] 2> 181081 T456 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1438800315724857344)]} 0 0
[junit4:junit4] 2> 181089 T512 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1438800315729051648)]} 0 1
[junit4:junit4] 2> 181091 T478 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1438800315729051648)]} 0 6
[junit4:junit4] 2> 181096 T459 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1438800315739537408)]} 0 1
[junit4:junit4] 2> 181102 T526 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1438800315744780288)]} 0 1
[junit4:junit4] 2> 181102 T496 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1438800315744780288)]} 0 3
[junit4:junit4] 2> 181105 T460 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1438800315748974592)]} 0 1
[junit4:junit4] 2> 181111 T527 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1438800315753168896)]} 0 0
[junit4:junit4] 2> 181113 T497 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1438800315753168896)]} 0 6
[junit4:junit4] 2> 181116 T457 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1438800315760508928)]} 0 1
[junit4:junit4] 2> 181120 T511 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1438800315762606080)]} 0 1
[junit4:junit4] 2> 181120 T476 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1438800315762606080)]} 0 3
[junit4:junit4] 2> 181123 T455 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1438800315768897536)]} 0 0
[junit4:junit4] 2> 181130 T529 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1438800315773091840)]} 0 0
[junit4:junit4] 2> 181132 T493 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!52 (1438800315773091840)]} 0 5
[junit4:junit4] 2> 181132 T481 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52]} 0 7
[junit4:junit4] 2> 181135 T458 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1438800315781480448)]} 0 0
[junit4:junit4] 2> 181145 T508 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1438800315787771904)]} 0 1
[junit4:junit4] 2> 181145 T477 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!53 (1438800315787771904)]} 0 4
[junit4:junit4] 2> 181146 T492 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53]} 0 8
[junit4:junit4] 2> 181151 T456 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1438800315797209088)]} 0 1
[junit4:junit4] 2> 181157 T513 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1438800315801403392)]} 0 1
[junit4:junit4] 2> 181158 T479 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1438800315801403392)]} 0 4
[junit4:junit4] 2> 181164 T459 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55 (1438800315811889152)]} 0 0
[junit4:junit4] 2> 181174 T528 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1438800315819229184)]} 0 0
[junit4:junit4] 2> 181176 T494 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!55 (1438800315819229184)]} 0 5
[junit4:junit4] 2> 181177 T475 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55]} 0 9
[junit4:junit4] 2> 181182 T460 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1438800315830763520)]} 0 1
[junit4:junit4] 2> 181193 T530 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1438800315838103552)]} 0 1
[junit4:junit4] 2> 181196 T495 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!56 (1438800315838103552)]} 0 7
[junit4:junit4] 2> 181198 T478 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56]} 0 12
[junit4:junit4] 2> 181202 T457 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1438800315851735040)]} 0 0
[junit4:junit4] 2> 181213 T525 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1438800315859075072)]} 0 1
[junit4:junit4] 2> 181219 T496 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!57 (1438800315859075072)]} 0 11
[junit4:junit4] 2> 181221 T481 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57]} 0 15
[junit4:junit4] 2> 181224 T455 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58 (1438800315874803712)]} 0 0
[junit4:junit4] 2> 181233 T509 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1438800315880046592)]} 0 0
[junit4:junit4] 2> 181235 T477 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!58 (1438800315880046592)]} 0 6
[junit4:junit4] 2> 181236 T497 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58]} 0 9
[junit4:junit4] 2> 181239 T458 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1438800315889483776)]} 0 1
[junit4:junit4] 2> 181249 T510 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1438800315898920960)]} 0 0
[junit4:junit4] 2> 181249 T479 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1438800315898920960)]} 0 3
[junit4:junit4] 2> 181253 T456 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1438800315904163840)]} 0 1
[junit4:junit4] 2> 181260 T512 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1438800315908358144)]} 0 0
[junit4:junit4] 2> 181264 T475 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1438800315908358144)]} 0 8
[junit4:junit4] 2> 181266 T460 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1438800315918843904)]} 0 0
[junit4:junit4] 2> 181273 T511 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1438800315924086784)]} 0 0
[junit4:junit4] 2> 181274 T478 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1438800315924086784)]} 0 3
[junit4:junit4] 2> 181277 T457 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62 (1438800315930378240)]} 0 0
[junit4:junit4] 2> 181284 T508 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!62 (1438800315934572544)]} 0 0
[junit4:junit4] 2> 181285 T476 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!62 (1438800315934572544)]} 0 4
[junit4:junit4] 2> 181285 T493 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62]} 0 5
[junit4:junit4] 2> 181288 T455 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63 (1438800315940864000)]} 0 1
[junit4:junit4] 2> 181295 T526 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!63 (1438800315946106880)]} 0 1
[junit4:junit4] 2> 181296 T492 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!63 (1438800315946106880)]} 0 4
[junit4:junit4] 2> 181297 T481 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63]} 0 7
[junit4:junit4] 2> 181302 T458 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!64 (1438800315955544064)]} 0 1
[junit4:junit4] 2> 181312 T529 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!64 (1438800315963932672)]} 0 0
[junit4:junit4] 2> 181326 T494 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!64 (1438800315963932672)]} 0 17
[junit4:junit4] 2> 181327 T477 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!64]} 0 22
[junit4:junit4] 2> 181330 T456 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!65 (1438800315984904192)]} 0 1
[junit4:junit4] 2> 181335 T513 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!65 (1438800315989098496)]} 0 0
[junit4:junit4] 2> 181337 T479 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!65 (1438800315989098496)]} 0 4
[junit4:junit4] 2> 181337 T496 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!65]} 0 6
[junit4:junit4] 2> 181341 T459 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!66 (1438800315996438528)]} 0 1
[junit4:junit4] 2> 181349 T528 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!66 (1438800316003778560)]} 0 0
[junit4:junit4] 2> 181352 T497 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!66 (1438800316003778560)]} 0 5
[junit4:junit4] 2> 181353 T475 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!66]} 0 8
[junit4:junit4] 2> 181356 T460 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!67 (1438800316013215744)]} 0 0
[junit4:junit4] 2> 181369 T510 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!67 (1438800316019507200)]} 0 0
[junit4:junit4] 2> 181371 T478 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!67 (1438800316019507200)]} 0 11
[junit4:junit4] 2> 181375 T457 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!68 (1438800316033138688)]} 0 1
[junit4:junit4] 2> 181382 T512 C69 P64511 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!68 (1438800316036284416)]} 0 0
[junit4:junit4] 2> 181383 T476 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!68 (1438800316036284416)]} 0 5
[junit4:junit4] 2> 181385 T455 C67 P64481 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!69 (1438800316043624448)]} 0 0
[junit4:junit4] 2> 181394 T530 C65 P64521 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64502/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!69 (1438800316049915904)]} 0 1
[junit4:junit4] 2> 181394 T493 C66 P64502 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:64493/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!69 (1438800316049915904)]} 0 3
[junit4:junit4] 2> 181395 T481 C68 P64493 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!69]} 0 7
[junit4:junit4] 2> 181401 T458 C67 P64481 oasup.LogUpdateProcessor.finish [collectio
[...truncated too long message...]
junit4] 2> at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
[junit4:junit4] 2> at java.net.Socket.connect(Socket.java:579)
[junit4:junit4] 2> at org.apache.http.conn.scheme.PlainSocketFactory.connectSocket(PlainSocketFactory.java:127)
[junit4:junit4] 2> at org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection(DefaultClientConnectionOperator.java:180)
[junit4:junit4] 2> ... 12 more
[junit4:junit4] 2>
[junit4:junit4] 2> 222625 T443 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 222625 T443 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 222633 T443 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@333cf5e3
[junit4:junit4] 2> 222656 T443 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=2,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=221,adds=221,deletesById=111,deletesByQuery=0,errors=0,cumulative_adds=263,cumulative_deletesById=111,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 222657 T443 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 222657 T443 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 222657 T443 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> C105_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:64521_, base_url=http://127.0.0.1:64521, leader=true}
[junit4:junit4] 2> 222668 T443 C105 P64521 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@138d7b91 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65605543),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@138d7b91 lockFactory=org.apache.lucene.store.NativeFSLockFactory@65605543),segFN=segments_5,generation=5}
[junit4:junit4] 2> 222668 T443 C105 P64521 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 222675 T443 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 222675 T443 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 222675 T443 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty4\ [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty4\;done=false>>]
[junit4:junit4] 2> 222678 T443 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty4\
[junit4:junit4] 2> 222678 T443 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty4\index [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty4\index;done=false>>]
[junit4:junit4] 2> 222678 T443 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ShardSplitTest-1372146885365/jetty4\index
[junit4:junit4] 2> 222679 T569 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89925018279804940-127.0.0.1:64521_-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 222683 T534 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> 222697 T443 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-1372146885365\zookeeper\server1\data\version-2\log.1 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-1372146885365\zookeeper\server1\data\version-2 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-1372146885365\zookeeper\server1\data FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-1372146885365\zookeeper\server1 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-1372146885365\zookeeper FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-1372146885365 FAILED !!!!!
[junit4:junit4] 2> 222810 T443 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 222812 T443 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:64474 64474
[junit4:junit4] 2> 222919 T517 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 225632 T517 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> 225633 T517 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 224312 T534 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 225639 T534 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 225639 T443 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 64481
[junit4:junit4] 2> 225675 T443 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 225676 T443 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:64474 64474
[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=90D8ADA3A986CE32 -Dtests.slow=true -Dtests.locale=hu -Dtests.timezone=Etc/GMT+10 -Dtests.file.encoding=UTF-8
[junit4:junit4] ERROR 66.8s | ShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:64493 returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([90D8ADA3A986CE32:113E23BBDED9AE0E]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:150)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:835)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:724)
[junit4:junit4] 2> 225740 T443 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=Pulsing41(freqCutoff=8 minBlockSize=86 maxBlockSize=204), _version_=Lucene41(blocksize=128), n_ti=Lucene41(blocksize=128)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=true,coord=no): {}, locale=hu, timezone=Etc/GMT+10
[junit4:junit4] 2> NOTE: Windows 7 6.1 amd64/Oracle Corporation 1.7.0_25 (64-bit)/cpus=2,threads=3,free=145957120,total=249823232
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestFastOutputStream, TestNumberUtils, TestFunctionQuery, TestQuerySenderNoQuery, TestLRUCache, ShowFileRequestHandlerTest, SliceStateTest, ZkCLITest, XmlUpdateRequestHandlerTest, DateFieldTest, QueryParsingTest, TestValueSourceCache, DistributedTermsComponentTest, NotRequiredUniqueKeyTest, SyncSliceTest, ShardSplitTest]
[junit4:junit4] Completed in 66.87s, 1 test, 1 error <<< FAILURES!
[...truncated 882 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:386: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:366: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build.xml:181: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\common-build.xml:437: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:1243: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:887: There were test failures: 297 suites, 1253 tests, 1 error, 18 ignored (12 assumptions)
Total time: 64 minutes 7 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0_25 -XX:-UseCompressedOops -XX:+UseParallelGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure