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/08 15:32:37 UTC
[JENKINS] Lucene-Solr-4.x-Windows (32bit/jdk1.7.0_21) - Build #
2868 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-Windows/2868/
Java: 32bit/jdk1.7.0_21 -client -XX:+UseConcMarkSweepGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:50293 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:50293 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([8D3F349626E11ACA:CD9BA8E51BE7AF6]: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:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 10108 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 2462833 T6923 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 2462838 T6923 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\solrtest-ShardSplitTest-1370698139611
[junit4:junit4] 2> 2462841 T6923 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 2462842 T6924 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 2462942 T6923 oasc.ZkTestServer.run start zk server on port:50274
[junit4:junit4] 2> 2462946 T6923 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2462960 T6930 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@11e979c name:ZooKeeperConnection Watcher:127.0.0.1:50274 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2462961 T6923 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2462961 T6923 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 2462975 T6925 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f23f9c7e40000, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 2462980 T6923 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2462988 T6932 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1e4a519 name:ZooKeeperConnection Watcher:127.0.0.1:50274/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2462988 T6923 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2462989 T6923 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 2463002 T6923 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 2463013 T6923 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 2463022 T6923 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 2463034 T6923 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 2463035 T6923 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 2463053 T6923 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 2463055 T6923 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 2463067 T6923 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 2463069 T6923 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 2463079 T6923 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 2463080 T6923 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 2463086 T6923 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 2463087 T6923 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 2463093 T6923 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 2463093 T6923 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 2463098 T6923 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 2463099 T6923 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 2463104 T6923 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 2463105 T6923 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 2463110 T6923 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 2463110 T6923 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 2463116 T6925 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f23f9c7e40001, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 2463562 T6923 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2463569 T6923 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50281
[junit4:junit4] 2> 2463569 T6923 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2463569 T6923 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2463570 T6923 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1370698139887
[junit4:junit4] 2> 2463570 T6923 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1370698139887\solr.xml
[junit4:junit4] 2> 2463571 T6923 oasc.CoreContainer.<init> New CoreContainer 19258132
[junit4:junit4] 2> 2463572 T6923 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1370698139887\'
[junit4:junit4] 2> 2463575 T6923 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1370698139887\'
[junit4:junit4] 2> 2463695 T6923 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2463696 T6923 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2463696 T6923 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2463697 T6923 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2463697 T6923 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2463697 T6923 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2463697 T6923 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2463697 T6923 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2463697 T6923 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2463698 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2463707 T6923 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2463708 T6923 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50274/solr
[junit4:junit4] 2> 2463709 T6923 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2463711 T6923 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2463725 T6943 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2ed2eb name:ZooKeeperConnection Watcher:127.0.0.1:50274 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2463725 T6923 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2463732 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2463740 T6923 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2463748 T6945 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6f9433 name:ZooKeeperConnection Watcher:127.0.0.1:50274/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2463749 T6923 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2463757 T6923 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 2463772 T6923 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 2463783 T6923 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 2463791 T6923 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50281_
[junit4:junit4] 2> 2463797 T6923 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50281_
[junit4:junit4] 2> 2463808 T6923 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 2463822 T6923 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 2463826 T6923 oasc.Overseer.start Overseer (id=89830073278136323-127.0.0.1:50281_-n_0000000000) starting
[junit4:junit4] 2> 2463833 T6923 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 2463842 T6947 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 2463843 T6923 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 2463848 T6923 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 2463851 T6923 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2463855 T6946 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 2463861 T6948 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1370698139887\collection1
[junit4:junit4] 2> 2463861 T6948 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 2463862 T6948 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2463862 T6948 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 2463864 T6948 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1370698139887\collection1\'
[junit4:junit4] 2> 2463866 T6948 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1370698139887/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2463867 T6948 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1370698139887/collection1/lib/README' to classloader
[junit4:junit4] 2> 2463931 T6948 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2464009 T6948 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2464013 T6948 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2464021 T6948 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2464694 T6948 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2464697 T6948 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2464700 T6948 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2464706 T6948 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2464739 T6948 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2464739 T6948 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1370698139887\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1370698139610/control/data\
[junit4:junit4] 2> 2464739 T6948 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bcd1f4
[junit4:junit4] 2> 2464739 T6948 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2464740 T6948 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1370698139610/control/data\
[junit4:junit4] 2> 2464740 T6948 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1370698139610/control/data\index/
[junit4:junit4] 2> 2464741 T6948 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1370698139610\control\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2464741 T6948 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1370698139610/control/data\index
[junit4:junit4] 2> 2464747 T6948 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@133e32c lockFactory=org.apache.lucene.store.NativeFSLockFactory@1826095),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2464747 T6948 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2464751 T6948 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2464751 T6948 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2464752 T6948 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2464753 T6948 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2464753 T6948 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2464753 T6948 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2464754 T6948 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2464754 T6948 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2464755 T6948 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2464771 T6948 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2464779 T6948 oass.SolrIndexSearcher.<init> Opening Searcher@1b15653 main
[junit4:junit4] 2> 2464779 T6948 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1370698139610\control\data\tlog
[junit4:junit4] 2> 2464780 T6948 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2464781 T6948 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2464786 T6949 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1b15653 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2464787 T6948 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2464787 T6948 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2465361 T6946 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2465362 T6946 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:50281_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50281"}
[junit4:junit4] 2> 2465363 T6946 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 2465363 T6946 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 2465372 T6945 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> 2465791 T6948 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2465791 T6948 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50281 collection:control_collection shard:shard1
[junit4:junit4] 2> 2465793 T6948 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 2465829 T6948 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2465841 T6948 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2465842 T6948 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2465843 T6948 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50281/collection1/
[junit4:junit4] 2> 2465843 T6948 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2465844 T6948 oasc.SyncStrategy.syncToMe http://127.0.0.1:50281/collection1/ has no replicas
[junit4:junit4] 2> 2465844 T6948 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50281/collection1/
[junit4:junit4] 2> 2465845 T6948 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 2466881 T6946 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2466897 T6945 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> 2466940 T6948 oasc.ZkController.register We are http://127.0.0.1:50281/collection1/ and leader is http://127.0.0.1:50281/collection1/
[junit4:junit4] 2> 2466940 T6948 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50281
[junit4:junit4] 2> 2466940 T6948 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2466941 T6948 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2466941 T6948 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2466945 T6948 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2466946 T6923 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2466947 T6923 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2466947 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2466954 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 2466957 T6923 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2466961 T6952 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d2b2af name:ZooKeeperConnection Watcher:127.0.0.1:50274/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2466962 T6923 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2466963 T6923 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2466967 T6923 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 2467405 T6923 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2467409 T6923 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50293
[junit4:junit4] 2> 2467409 T6923 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2467409 T6923 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2467409 T6923 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1370698143738
[junit4:junit4] 2> 2467410 T6923 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1370698143738\solr.xml
[junit4:junit4] 2> 2467411 T6923 oasc.CoreContainer.<init> New CoreContainer 16674886
[junit4:junit4] 2> 2467411 T6923 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1370698143738\'
[junit4:junit4] 2> 2467412 T6923 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1370698143738\'
[junit4:junit4] 2> 2467539 T6923 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2467539 T6923 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2467539 T6923 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2467540 T6923 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2467540 T6923 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2467540 T6923 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2467542 T6923 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2467542 T6923 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2467542 T6923 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2467543 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2467551 T6923 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2467552 T6923 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50274/solr
[junit4:junit4] 2> 2467552 T6923 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2467554 T6923 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2467572 T6963 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1592e85 name:ZooKeeperConnection Watcher:127.0.0.1:50274 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2467573 T6923 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2467577 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2467580 T6925 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13f23f9c7e40005, likely client has closed socket
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220)
[junit4:junit4] 2> at org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208)
[junit4:junit4] 2> at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2>
[junit4:junit4] 2> 2467585 T6923 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2467589 T6965 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f00876 name:ZooKeeperConnection Watcher:127.0.0.1:50274/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2467589 T6923 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2467597 T6923 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2468408 T6946 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2468411 T6946 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:50281_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50281"}
[junit4:junit4] 2> 2468431 T6965 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> 2468431 T6945 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> 2468432 T6952 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> 2468603 T6923 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50293_
[junit4:junit4] 2> 2468609 T6923 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50293_
[junit4:junit4] 2> 2468619 T6965 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 2468619 T6945 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 2468620 T6945 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> 2468619 T6965 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> 2468622 T6952 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 2468622 T6952 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> 2468649 T6966 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1370698143738\collection1
[junit4:junit4] 2> 2468649 T6966 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2468651 T6966 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2468651 T6966 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2468657 T6966 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1370698143738\collection1\'
[junit4:junit4] 2> 2468660 T6966 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1370698143738/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2468662 T6966 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1370698143738/collection1/lib/README' to classloader
[junit4:junit4] 2> 2468731 T6966 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2468819 T6966 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2468822 T6966 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2468829 T6966 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2469519 T6966 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2469523 T6966 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2469525 T6966 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2469532 T6966 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2469565 T6966 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2469566 T6966 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1370698143738\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty1\
[junit4:junit4] 2> 2469566 T6966 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bcd1f4
[junit4:junit4] 2> 2469567 T6966 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2469567 T6966 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty1\
[junit4:junit4] 2> 2469567 T6966 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty1\index/
[junit4:junit4] 2> 2469568 T6966 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1370698139610\jetty1\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2469568 T6966 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty1\index
[junit4:junit4] 2> 2469572 T6966 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c8f4e5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c18697),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2469572 T6966 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2469575 T6966 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2469576 T6966 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2469576 T6966 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2469577 T6966 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2469578 T6966 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2469578 T6966 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2469579 T6966 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2469579 T6966 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2469580 T6966 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2469591 T6966 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2469599 T6966 oass.SolrIndexSearcher.<init> Opening Searcher@1ccb269 main
[junit4:junit4] 2> 2469599 T6966 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1370698139610\jetty1\tlog
[junit4:junit4] 2> 2469601 T6966 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2469601 T6966 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2469606 T6967 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1ccb269 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2469608 T6966 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2469608 T6966 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2469948 T6946 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2469950 T6946 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:50293_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50293"}
[junit4:junit4] 2> 2469951 T6946 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 2469951 T6946 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 2469971 T6965 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> 2469972 T6945 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> 2469971 T6952 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> 2470615 T6966 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2470615 T6966 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50293 collection:collection1 shard:shard1
[junit4:junit4] 2> 2470617 T6966 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 2470632 T6966 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2470637 T6966 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2470638 T6966 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2470638 T6966 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50293/collection1/
[junit4:junit4] 2> 2470638 T6966 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2470639 T6966 oasc.SyncStrategy.syncToMe http://127.0.0.1:50293/collection1/ has no replicas
[junit4:junit4] 2> 2470639 T6966 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50293/collection1/
[junit4:junit4] 2> 2470639 T6966 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 2471488 T6946 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2471525 T6965 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> 2471526 T6945 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> 2471525 T6952 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> 2471566 T6966 oasc.ZkController.register We are http://127.0.0.1:50293/collection1/ and leader is http://127.0.0.1:50293/collection1/
[junit4:junit4] 2> 2471567 T6966 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50293
[junit4:junit4] 2> 2471567 T6966 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2471568 T6966 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2471568 T6966 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2471573 T6966 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2471577 T6923 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2471578 T6923 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2471580 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2472008 T6923 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2472015 T6923 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50302
[junit4:junit4] 2> 2472016 T6923 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2472017 T6923 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2472017 T6923 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1370698148365
[junit4:junit4] 2> 2472018 T6923 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1370698148365\solr.xml
[junit4:junit4] 2> 2472018 T6923 oasc.CoreContainer.<init> New CoreContainer 12918202
[junit4:junit4] 2> 2472019 T6923 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1370698148365\'
[junit4:junit4] 2> 2472019 T6923 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1370698148365\'
[junit4:junit4] 2> 2472138 T6923 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2472139 T6923 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2472139 T6923 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2472139 T6923 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2472140 T6923 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2472140 T6923 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2472141 T6923 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2472141 T6923 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2472142 T6923 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2472143 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2472151 T6923 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2472152 T6923 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50274/solr
[junit4:junit4] 2> 2472152 T6923 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2472155 T6923 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2472171 T6979 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a1af5d name:ZooKeeperConnection Watcher:127.0.0.1:50274 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2472171 T6923 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2472175 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2472182 T6923 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2472186 T6981 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1a46db5 name:ZooKeeperConnection Watcher:127.0.0.1:50274/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2472186 T6923 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2472195 T6923 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2473085 T6946 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2473087 T6946 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:50293_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50293"}
[junit4:junit4] 2> 2473113 T6965 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> 2473114 T6981 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> 2473115 T6945 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> 2473114 T6952 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> 2473251 T6923 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50302_
[junit4:junit4] 2> 2473258 T6923 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50302_
[junit4:junit4] 2> 2473267 T6981 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> 2473270 T6952 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2473270 T6952 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> 2473273 T6965 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2473274 T6965 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> 2473274 T6945 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2473276 T6945 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> 2473284 T6981 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 2473304 T6982 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1370698148365\collection1
[junit4:junit4] 2> 2473304 T6982 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2473307 T6982 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2473307 T6982 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2473315 T6982 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1370698148365\collection1\'
[junit4:junit4] 2> 2473319 T6982 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1370698148365/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2473321 T6982 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1370698148365/collection1/lib/README' to classloader
[junit4:junit4] 2> 2473385 T6982 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2473463 T6982 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2473466 T6982 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2473475 T6982 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2474198 T6982 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2474202 T6982 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2474204 T6982 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2474211 T6982 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2474247 T6982 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2474248 T6982 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1370698148365\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty2\
[junit4:junit4] 2> 2474248 T6982 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bcd1f4
[junit4:junit4] 2> 2474248 T6982 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2474249 T6982 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty2\
[junit4:junit4] 2> 2474249 T6982 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty2\index/
[junit4:junit4] 2> 2474249 T6982 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1370698139610\jetty2\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2474250 T6982 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty2\index
[junit4:junit4] 2> 2474256 T6982 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1007ec9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@83dcf6),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2474256 T6982 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2474260 T6982 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2474261 T6982 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2474261 T6982 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2474262 T6982 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2474263 T6982 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2474263 T6982 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2474264 T6982 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2474265 T6982 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2474265 T6982 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2474278 T6982 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2474289 T6982 oass.SolrIndexSearcher.<init> Opening Searcher@17d701f main
[junit4:junit4] 2> 2474290 T6982 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1370698139610\jetty2\tlog
[junit4:junit4] 2> 2474292 T6982 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2474293 T6982 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2474301 T6983 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@17d701f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2474302 T6982 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2474302 T6982 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2474785 T6946 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2474787 T6946 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:50302_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50302"}
[junit4:junit4] 2> 2474789 T6946 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 2474789 T6946 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 2474815 T6965 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> 2474816 T6952 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> 2474816 T6945 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> 2474816 T6981 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> 2475407 T6982 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2475407 T6982 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50302 collection:collection1 shard:shard2
[junit4:junit4] 2> 2475411 T6982 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 2475440 T6982 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 2475452 T6982 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 2475453 T6982 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 2475453 T6982 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50302/collection1/
[junit4:junit4] 2> 2475455 T6982 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 2475456 T6982 oasc.SyncStrategy.syncToMe http://127.0.0.1:50302/collection1/ has no replicas
[junit4:junit4] 2> 2475456 T6982 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50302/collection1/
[junit4:junit4] 2> 2475457 T6982 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 2476486 T6946 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2476522 T6965 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> 2476523 T6981 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> 2476524 T6945 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> 2476523 T6952 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> 2476542 T6982 oasc.ZkController.register We are http://127.0.0.1:50302/collection1/ and leader is http://127.0.0.1:50302/collection1/
[junit4:junit4] 2> 2476543 T6982 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50302
[junit4:junit4] 2> 2476543 T6982 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 2476544 T6982 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2476544 T6982 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2476551 T6982 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2476555 T6923 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2476556 T6923 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2476558 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2477094 T6923 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2477099 T6923 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50311
[junit4:junit4] 2> 2477099 T6923 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2477100 T6923 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2477100 T6923 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1370698153348
[junit4:junit4] 2> 2477101 T6923 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1370698153348\solr.xml
[junit4:junit4] 2> 2477101 T6923 oasc.CoreContainer.<init> New CoreContainer 30840940
[junit4:junit4] 2> 2477102 T6923 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1370698153348\'
[junit4:junit4] 2> 2477102 T6923 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1370698153348\'
[junit4:junit4] 2> 2477246 T6923 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2477246 T6923 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2477247 T6923 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2477247 T6923 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2477248 T6923 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2477250 T6923 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2477250 T6923 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2477251 T6923 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2477251 T6923 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2477251 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2477261 T6923 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2477261 T6923 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50274/solr
[junit4:junit4] 2> 2477262 T6923 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2477265 T6923 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2477283 T6995 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@181b37c name:ZooKeeperConnection Watcher:127.0.0.1:50274 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2477284 T6923 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2477287 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2477298 T6923 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2477302 T6997 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2d1237 name:ZooKeeperConnection Watcher:127.0.0.1:50274/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2477302 T6923 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2477310 T6923 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2478205 T6946 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2478207 T6946 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:50302_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50302"}
[junit4:junit4] 2> 2478229 T6952 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> 2478229 T6997 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> 2478230 T6981 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> 2478229 T6945 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> 2478229 T6965 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> 2478415 T6923 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50311_
[junit4:junit4] 2> 2478420 T6923 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50311_
[junit4:junit4] 2> 2478432 T6997 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> 2478433 T6981 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> 2478434 T6965 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2478435 T6965 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> 2478435 T6945 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2478438 T6945 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> 2478435 T6952 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2478440 T6952 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> 2478445 T6981 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2478446 T6997 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 2478470 T6998 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1370698153348\collection1
[junit4:junit4] 2> 2478471 T6998 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2478473 T6998 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2478474 T6998 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2478482 T6998 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1370698153348\collection1\'
[junit4:junit4] 2> 2478487 T6998 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1370698153348/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2478490 T6998 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1370698153348/collection1/lib/README' to classloader
[junit4:junit4] 2> 2478572 T6998 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2478646 T6998 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2478649 T6998 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2478660 T6998 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2479412 T6998 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2479417 T6998 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2479419 T6998 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2479428 T6998 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2479476 T6998 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2479476 T6998 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1370698153348\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty3\
[junit4:junit4] 2> 2479476 T6998 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bcd1f4
[junit4:junit4] 2> 2479477 T6998 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2479477 T6998 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty3\
[junit4:junit4] 2> 2479479 T6998 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty3\index/
[junit4:junit4] 2> 2479479 T6998 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1370698139610\jetty3\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2479479 T6998 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty3\index
[junit4:junit4] 2> 2479484 T6998 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a0aad1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17004e6),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2479484 T6998 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2479488 T6998 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2479488 T6998 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2479488 T6998 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2479489 T6998 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2479490 T6998 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2479490 T6998 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2479491 T6998 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2479491 T6998 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2479492 T6998 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2479503 T6998 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2479512 T6998 oass.SolrIndexSearcher.<init> Opening Searcher@19c6af1 main
[junit4:junit4] 2> 2479512 T6998 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1370698139610\jetty3\tlog
[junit4:junit4] 2> 2479514 T6998 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2479514 T6998 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2479520 T6999 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@19c6af1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2479523 T6998 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2479524 T6998 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2479902 T6946 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2479904 T6946 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:50311_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50311"}
[junit4:junit4] 2> 2479904 T6946 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 2479905 T6946 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 2479923 T6952 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> 2479924 T6997 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> 2479926 T6981 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> 2479924 T6945 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> 2479924 T6965 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> 2480629 T6998 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2480629 T6998 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50311 collection:collection1 shard:shard1
[junit4:junit4] 2> 2480641 T6998 oasc.ZkController.register We are http://127.0.0.1:50311/collection1/ and leader is http://127.0.0.1:50293/collection1/
[junit4:junit4] 2> 2480642 T6998 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50311
[junit4:junit4] 2> 2480642 T6998 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 2480643 T6998 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C6649 name=collection1 org.apache.solr.core.SolrCore@fe7370 url=http://127.0.0.1:50311/collection1 node=127.0.0.1:50311_ C6649_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:50311_, base_url=http://127.0.0.1:50311}
[junit4:junit4] 2> 2480645 T7000 C6649 P50311 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 2480645 T7000 C6649 P50311 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 2480646 T7000 C6649 P50311 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 2480646 T7000 C6649 P50311 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2480647 T6998 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2480652 T7000 C6649 P50311 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2480655 T6923 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2480656 T6923 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2480656 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2480671 T6958 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 2481107 T6923 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 2481115 T6923 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50321
[junit4:junit4] 2> 2481115 T6923 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 2481115 T6923 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 2481115 T6923 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1370698157440
[junit4:junit4] 2> 2481116 T6923 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1370698157440\solr.xml
[junit4:junit4] 2> 2481116 T6923 oasc.CoreContainer.<init> New CoreContainer 30389811
[junit4:junit4] 2> 2481117 T6923 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1370698157440\'
[junit4:junit4] 2> 2481117 T6923 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1370698157440\'
[junit4:junit4] 2> 2481242 T6923 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 2481242 T6923 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 2481243 T6923 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 2481245 T6923 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 2481245 T6923 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 2481246 T6923 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 2481246 T6923 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 2481246 T6923 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 2481246 T6923 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 2481247 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 2481254 T6923 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 2481256 T6923 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50274/solr
[junit4:junit4] 2> 2481256 T6923 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 2481260 T6923 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2481280 T7012 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1c61c90 name:ZooKeeperConnection Watcher:127.0.0.1:50274 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2481280 T6923 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2481289 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 2481305 T6923 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 2481308 T7014 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@174ee94 name:ZooKeeperConnection Watcher:127.0.0.1:50274/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 2481309 T6923 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 2481316 T6923 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 2481598 T6946 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2481600 T6946 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:50311_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50311"}
[junit4:junit4] 2> 2481619 T6952 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> 2481620 T7014 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> 2481620 T6965 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> 2481620 T6981 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> 2481620 T6997 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> 2481620 T6945 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> 2481771 T6958 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 2481772 T6958 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:50311_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1102
[junit4:junit4] 2> 2482422 T6923 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50321_
[junit4:junit4] 2> 2482428 T6923 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50321_
[junit4:junit4] 2> 2482440 T6997 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> 2482441 T6981 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> 2482443 T6952 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2482444 T6952 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> 2482444 T7014 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2482445 T7014 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> 2482448 T6965 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2482449 T6965 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> 2482451 T6945 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2482452 T6945 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> 2482462 T6981 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2482464 T6997 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 2482486 T7015 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1370698157440\collection1
[junit4:junit4] 2> 2482486 T7015 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 2482488 T7015 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 2482490 T7015 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 2482496 T7015 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1370698157440\collection1\'
[junit4:junit4] 2> 2482500 T7015 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1370698157440/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 2482502 T7015 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-4.x-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1370698157440/collection1/lib/README' to classloader
[junit4:junit4] 2> 2482575 T7015 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 2482653 T7015 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 2482656 T7015 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 2482671 T7015 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 2483398 T7015 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 2483403 T7015 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 2483405 T7015 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2483420 T7015 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 2483456 T7015 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2483456 T7015 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1370698157440\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty4\
[junit4:junit4] 2> 2483456 T7015 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@bcd1f4
[junit4:junit4] 2> 2483457 T7015 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 2483457 T7015 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty4\
[junit4:junit4] 2> 2483458 T7015 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty4\index/
[junit4:junit4] 2> 2483458 T7015 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1370698139610\jetty4\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 2483458 T7015 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty4\index
[junit4:junit4] 2> 2483464 T7015 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@317ec5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a2f8ba),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2483464 T7015 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2483468 T7015 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 2483469 T7015 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 2483469 T7015 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 2483470 T7015 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 2483471 T7015 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 2483472 T7015 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 2483472 T7015 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 2483473 T7015 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 2483475 T7015 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 2483487 T7015 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 2483496 T7015 oass.SolrIndexSearcher.<init> Opening Searcher@117cb94 main
[junit4:junit4] 2> 2483496 T7015 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1370698139610\jetty4\tlog
[junit4:junit4] 2> 2483498 T7015 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 2483498 T7015 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 2483505 T7016 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@117cb94 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 2483507 T7015 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 2483507 T7015 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> ASYNC NEW_CORE C6650 name=collection1 org.apache.solr.core.SolrCore@fe7370 url=http://127.0.0.1:50311/collection1 node=127.0.0.1:50311_ C6650_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:50311_, base_url=http://127.0.0.1:50311}
[junit4:junit4] 2> 2483946 T7000 C6650 P50311 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50293/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 2483947 T7000 C6650 P50311 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50311 START replicas=[http://127.0.0.1:50293/collection1/] nUpdates=100
[junit4:junit4] 2> 2483949 T7000 C6650 P50311 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 2483949 T7000 C6650 P50311 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 2483950 T7000 C6650 P50311 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 2483950 T7000 C6650 P50311 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 2483950 T7000 C6650 P50311 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 2483951 T7000 C6650 P50311 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50293/collection1/. core=collection1
[junit4:junit4] 2> 2483951 T7000 C6650 P50311 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C6651 name=collection1 org.apache.solr.core.SolrCore@1d22cfb url=http://127.0.0.1:50293/collection1 node=127.0.0.1:50293_ C6651_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50293_, base_url=http://127.0.0.1:50293, leader=true}
[junit4:junit4] 2> 2483962 T6961 C6651 P50293 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> 2483964 T6956 C6651 P50293 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2483967 T6956 C6651 P50293 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c8f4e5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c18697),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2483968 T6956 C6651 P50293 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2483969 T6956 C6651 P50293 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c8f4e5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c18697),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c8f4e5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c18697),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2483969 T6956 C6651 P50293 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2483970 T6956 C6651 P50293 oass.SolrIndexSearcher.<init> Opening Searcher@1914a91 realtime
[junit4:junit4] 2> 2483970 T6956 C6651 P50293 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2483970 T6956 C6651 P50293 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> 2483972 T7000 C6650 P50311 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2483972 T7000 C6650 P50311 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 2483975 T6959 C6651 P50293 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2483975 T6959 C6651 P50293 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 2483976 T7000 C6650 P50311 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 2483976 T7000 C6650 P50311 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 2483976 T7000 C6650 P50311 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 2483978 T6960 C6651 P50293 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> 2483979 T7000 C6650 P50311 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 2483980 T7000 C6650 P50311 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty3\index.20130608192920750
[junit4:junit4] 2> 2483980 T7000 C6650 P50311 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@455229 lockFactory=org.apache.lucene.store.NativeFSLockFactory@976a63) fullCopy=false
[junit4:junit4] 2> 2483981 T6958 C6651 P50293 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> 2483982 T7000 C6650 P50311 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 2483983 T7000 C6650 P50311 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 2483983 T7000 C6650 P50311 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 2483986 T7000 C6650 P50311 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a0aad1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17004e6),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a0aad1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17004e6),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2483988 T7000 C6650 P50311 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2483988 T7000 C6650 P50311 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 2483988 T7000 C6650 P50311 oass.SolrIndexSearcher.<init> Opening Searcher@1af9a12 main
[junit4:junit4] 2> 2483989 T6999 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1af9a12 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2483991 T7000 C6650 P50311 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty3\index.20130608192920750 [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty3\index.20130608192920750;done=true>>]
[junit4:junit4] 2> 2483991 T7000 C6650 P50311 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty3\index.20130608192920750
[junit4:junit4] 2> 2483991 T7000 C6650 P50311 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty3\index.20130608192920750
[junit4:junit4] 2> 2483991 T7000 C6650 P50311 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 2483992 T7000 C6650 P50311 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 2483992 T7000 C6650 P50311 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2483992 T7000 C6650 P50311 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2483996 T7000 C6650 P50311 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 2484821 T6946 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2484823 T6946 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:50321_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50321"}
[junit4:junit4] 2> 2484823 T6946 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 2484824 T6946 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 2484840 T6946 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:50311_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50311"}
[junit4:junit4] 2> 2484856 T6952 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> 2484858 T6965 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> 2484859 T6945 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> 2484860 T6997 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> 2484858 T7014 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> 2484860 T6981 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> 2485513 T7015 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 2485513 T7015 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50321 collection:collection1 shard:shard2
[junit4:junit4] 2> 2485528 T7015 oasc.ZkController.register We are http://127.0.0.1:50321/collection1/ and leader is http://127.0.0.1:50302/collection1/
[junit4:junit4] 2> 2485528 T7015 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50321
[junit4:junit4] 2> 2485529 T7015 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 2485530 T7015 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C6652 name=collection1 org.apache.solr.core.SolrCore@119c6e0 url=http://127.0.0.1:50321/collection1 node=127.0.0.1:50321_ C6652_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:50321_, base_url=http://127.0.0.1:50321}
[junit4:junit4] 2> 2485532 T7019 C6652 P50321 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 2485532 T7019 C6652 P50321 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 2485533 T7019 C6652 P50321 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 2485533 T7019 C6652 P50321 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2485533 T7015 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2485539 T7019 C6652 P50321 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2485543 T6923 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 2485544 T6923 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 2485544 T6923 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 2485553 T6976 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 2485558 T6923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2485560 T6923 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 2485560 T6923 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 2485561 T6923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2486372 T6946 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2486374 T6946 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:50321_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50321"}
[junit4:junit4] 2> 2486394 T6952 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> 2486395 T6945 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> 2486395 T6997 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> 2486396 T7014 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> 2486395 T6981 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> 2486395 T6965 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> 2486543 T6976 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 2486544 T6976 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:50321_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=991
[junit4:junit4] 2> 2486553 T6923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2487546 T6923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C6652_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:50321_, base_url=http://127.0.0.1:50321}
[junit4:junit4] 2> 2488526 T7019 C6652 P50321 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50302/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 2488526 T7019 C6652 P50321 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50321 START replicas=[http://127.0.0.1:50302/collection1/] nUpdates=100
[junit4:junit4] 2> 2488528 T7019 C6652 P50321 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 2488529 T7019 C6652 P50321 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 2488530 T7019 C6652 P50321 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 2488532 T7019 C6652 P50321 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 2488532 T7019 C6652 P50321 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 2488533 T7019 C6652 P50321 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50302/collection1/. core=collection1
[junit4:junit4] 2> 2488533 T7019 C6652 P50321 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C6653 name=collection1 org.apache.solr.core.SolrCore@361f00 url=http://127.0.0.1:50302/collection1 node=127.0.0.1:50302_ C6653_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50302_, base_url=http://127.0.0.1:50302, leader=true}
[junit4:junit4] 2> 2488548 T6977 C6653 P50302 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> 2488549 T6923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2488554 T6976 C6653 P50302 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2488560 T6976 C6653 P50302 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1007ec9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@83dcf6),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2488561 T6976 C6653 P50302 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2488562 T6976 C6653 P50302 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1007ec9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@83dcf6),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1007ec9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@83dcf6),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2488562 T6976 C6653 P50302 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2488563 T6976 C6653 P50302 oass.SolrIndexSearcher.<init> Opening Searcher@108206e realtime
[junit4:junit4] 2> 2488563 T6976 C6653 P50302 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2488563 T6976 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 2488564 T7019 C6652 P50321 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2488564 T7019 C6652 P50321 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 2488566 T6974 C6653 P50302 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 2488567 T6974 C6653 P50302 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 2488567 T7019 C6652 P50321 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 2488568 T7019 C6652 P50321 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 2488568 T7019 C6652 P50321 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 2488570 T6975 C6653 P50302 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> 2488571 T7019 C6652 P50321 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 2488572 T7019 C6652 P50321 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty4\index.20130608192925342
[junit4:junit4] 2> 2488572 T7019 C6652 P50321 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1b3696c lockFactory=org.apache.lucene.store.NativeFSLockFactory@784a27) fullCopy=false
[junit4:junit4] 2> 2488574 T6977 C6653 P50302 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> 2488575 T7019 C6652 P50321 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 2488576 T7019 C6652 P50321 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 2488577 T7019 C6652 P50321 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 2488578 T7019 C6652 P50321 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@317ec5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a2f8ba),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@317ec5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a2f8ba),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2488580 T7019 C6652 P50321 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2488580 T7019 C6652 P50321 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 2488580 T7019 C6652 P50321 oass.SolrIndexSearcher.<init> Opening Searcher@110cc25 main
[junit4:junit4] 2> 2488581 T7016 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@110cc25 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2488581 T7019 C6652 P50321 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty4\index.20130608192925342 [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty4\index.20130608192925342;done=true>>]
[junit4:junit4] 2> 2488581 T7019 C6652 P50321 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty4\index.20130608192925342
[junit4:junit4] 2> 2488582 T7019 C6652 P50321 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: .\org.apache.solr.cloud.ShardSplitTest-1370698139610/jetty4\index.20130608192925342
[junit4:junit4] 2> 2488582 T7019 C6652 P50321 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 2488582 T7019 C6652 P50321 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 2488582 T7019 C6652 P50321 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 2488582 T7019 C6652 P50321 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 2488595 T7019 C6652 P50321 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 2489387 T6946 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2489389 T6946 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:50321_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50321"}
[junit4:junit4] 2> 2489408 T6952 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> 2489409 T6965 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> 2489410 T6945 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> 2489411 T6997 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> 2489409 T7014 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> 2489411 T6981 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> 2489542 T6923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2489543 T6923 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C6654 name=collection1 org.apache.solr.core.SolrCore@153e3a3 url=http://127.0.0.1:50281/collection1 node=127.0.0.1:50281_ C6654_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:50281_, base_url=http://127.0.0.1:50281, leader=true}
[junit4:junit4] 2> 2489558 T6940 C6654 P50281 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2489561 T6940 C6654 P50281 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@133e32c lockFactory=org.apache.lucene.store.NativeFSLockFactory@1826095),segFN=segments_1,generation=1}
[junit4:junit4] 2> 2489562 T6940 C6654 P50281 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 2489562 T6940 C6654 P50281 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@133e32c lockFactory=org.apache.lucene.store.NativeFSLockFactory@1826095),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@133e32c lockFactory=org.apache.lucene.store.NativeFSLockFactory@1826095),segFN=segments_2,generation=2}
[junit4:junit4] 2> 2489563 T6940 C6654 P50281 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 2489563 T6940 C6654 P50281 oass.SolrIndexSearcher.<init> Opening Searcher@1f53769 main
[junit4:junit4] 2> 2489564 T6940 C6654 P50281 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2489564 T6949 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f53769 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2489565 T6940 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 2489572 T6972 C6653 P50302 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2489574 T6972 C6653 P50302 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1007ec9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@83dcf6),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1007ec9 lockFactory=org.apache.lucene.store.NativeFSLockFactory@83dcf6),segFN=segments_3,generation=3}
[junit4:junit4] 2> 2489574 T6972 C6653 P50302 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 2489574 T6972 C6653 P50302 oass.SolrIndexSearcher.<init> Opening Searcher@1cdf954 main
[junit4:junit4] 2> 2489575 T6972 C6653 P50302 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2489576 T6983 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1cdf954 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2489577 T6972 C6653 P50302 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:50293/collection1/, StdNode: http://127.0.0.1:50311/collection1/, StdNode: http://127.0.0.1:50321/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 2489581 T6956 C6651 P50293 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2489585 T6956 C6651 P50293 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c8f4e5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c18697),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@c8f4e5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c18697),segFN=segments_3,generation=3}
[junit4:junit4] 2> 2489585 T6956 C6651 P50293 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 2489585 T6956 C6651 P50293 oass.SolrIndexSearcher.<init> Opening Searcher@a97cbe main
[junit4:junit4] 2> 2489587 T6967 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@a97cbe main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2489588 T6956 C6651 P50293 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2489588 T6956 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> C6652_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50321_, base_url=http://127.0.0.1:50321}
[junit4:junit4] 2> 2489589 T7006 C6652 P50321 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2489590 T7006 C6652 P50321 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@317ec5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a2f8ba),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@317ec5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@a2f8ba),segFN=segments_3,generation=3}
[junit4:junit4] 2> 2489591 T7006 C6652 P50321 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 2489592 T7006 C6652 P50321 oass.SolrIndexSearcher.<init> Opening Searcher@db4eb5 main
[junit4:junit4] 2> 2489592 T7006 C6652 P50321 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2489593 T7016 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@db4eb5 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2489594 T7006 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> C6650_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50311_, base_url=http://127.0.0.1:50311}
[junit4:junit4] 2> 2489599 T6992 C6650 P50311 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 2489600 T6992 C6650 P50311 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a0aad1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17004e6),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a0aad1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@17004e6),segFN=segments_3,generation=3}
[junit4:junit4] 2> 2489600 T6992 C6650 P50311 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 2489601 T6992 C6650 P50311 oass.SolrIndexSearcher.<init> Opening Searcher@8d7f6e main
[junit4:junit4] 2> 2489601 T6992 C6650 P50311 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 2489601 T6999 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@8d7f6e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 2489601 T6992 C6650 P50311 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 2
[junit4:junit4] 2> 2489602 T6972 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 30
[junit4:junit4] 2> 2489603 T6923 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 2489608 T6959 C6651 P50293 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> 2489611 T6993 C6650 P50311 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> 2489613 T6974 C6653 P50302 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> 2489616 T7007 C6652 P50321 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> 2491605 T6938 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437281202597789696)} 0 5
[junit4:junit4] 2> 2491621 T7005 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1437281202607226880&update.from=http://127.0.0.1:50302/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437281202607226880)} 0 6
[junit4:junit4] 2> 2491629 T6991 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1437281202613518336&update.from=http://127.0.0.1:50293/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437281202613518336)} 0 3
[junit4:junit4] 2> 2491631 T6957 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1437281202613518336)} 0 17
[junit4:junit4] 2> 2491633 T6976 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437281202607226880)} 0 24
[junit4:junit4] 2> 2491638 T6940 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1437281202635538432)]} 0 2
[junit4:junit4] 2> 2491644 T7006 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1437281202640781312)]} 0 1
[junit4:junit4] 2> 2491646 T6972 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!0 (1437281202640781312)]} 0 6
[junit4:junit4] 2> 2491650 T6941 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1 (1437281202650218496)]} 0 1
[junit4:junit4] 2> 2491661 T6992 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1437281202657558528)]} 0 1
[junit4:junit4] 2> 2491663 T6956 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!1 (1437281202657558528)]} 0 6
[junit4:junit4] 2> 2491664 T6974 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!1]} 0 10
[junit4:junit4] 2> 2491668 T6936 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1437281202669092864)]} 0 0
[junit4:junit4] 2> 2491675 T6993 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1437281202673287168)]} 0 1
[junit4:junit4] 2> 2491677 T6959 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!2 (1437281202673287168)]} 0 6
[junit4:junit4] 2> 2491680 T6937 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1437281202681675776)]} 0 0
[junit4:junit4] 2> 2491689 T7007 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1437281202687967232)]} 0 1
[junit4:junit4] 2> 2491690 T6975 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!3 (1437281202687967232)]} 0 5
[junit4:junit4] 2> 2491695 T6939 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1437281202697404416)]} 0 1
[junit4:junit4] 2> 2491702 T7008 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1437281202699501568)]} 0 1
[junit4:junit4] 2> 2491703 T6977 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!4 (1437281202699501568)]} 0 6
[junit4:junit4] 2> 2491708 T6938 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1437281202709987328)]} 0 1
[junit4:junit4] 2> 2491716 T7009 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1437281202715230208)]} 0 1
[junit4:junit4] 2> 2491717 T6973 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!5 (1437281202715230208)]} 0 5
[junit4:junit4] 2> 2491722 T6940 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1437281202724667392)]} 0 1
[junit4:junit4] 2> 2491729 T6988 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1437281202729910272)]} 0 1
[junit4:junit4] 2> 2491731 T6960 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!6 (1437281202729910272)]} 0 5
[junit4:junit4] 2> 2491735 T6941 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1437281202739347456)]} 0 0
[junit4:junit4] 2> 2491743 T6989 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1437281202743541760)]} 0 0
[junit4:junit4] 2> 2491745 T6958 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!7 (1437281202743541760)]} 0 6
[junit4:junit4] 2> 2491748 T6936 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8 (1437281202752978944)]} 0 0
[junit4:junit4] 2> 2491759 T6990 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1437281202761367552)]} 0 0
[junit4:junit4] 2> 2491761 T6961 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!8 (1437281202761367552)]} 0 5
[junit4:junit4] 2> 2491763 T6976 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!8]} 0 10
[junit4:junit4] 2> 2491766 T6937 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1437281202771853312)]} 0 0
[junit4:junit4] 2> 2491775 T6991 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1437281202777096192)]} 0 1
[junit4:junit4] 2> 2491777 T6957 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!9 (1437281202777096192)]} 0 6
[junit4:junit4] 2> 2491780 T6939 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1437281202786533376)]} 0 0
[junit4:junit4] 2> 2491789 T6992 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1437281202791776256)]} 0 1
[junit4:junit4] 2> 2491790 T6956 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!10 (1437281202791776256)]} 0 5
[junit4:junit4] 2> 2491794 T6938 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11 (1437281202801213440)]} 0 0
[junit4:junit4] 2> 2491806 T7010 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1437281202808553472)]} 0 0
[junit4:junit4] 2> 2491808 T6972 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!11 (1437281202808553472)]} 0 7
[junit4:junit4] 2> 2491809 T6959 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!11]} 0 11
[junit4:junit4] 2> 2491814 T6940 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12 (1437281202822184960)]} 0 1
[junit4:junit4] 2> 2491824 T7005 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1437281202829524992)]} 0 1
[junit4:junit4] 2> 2491825 T6974 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!12 (1437281202829524992)]} 0 5
[junit4:junit4] 2> 2491827 T6960 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!12]} 0 11
[junit4:junit4] 2> 2491831 T6941 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13 (1437281202838962176)]} 0 1
[junit4:junit4] 2> 2491841 T6993 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1437281202847350784)]} 0 1
[junit4:junit4] 2> 2491843 T6958 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!13 (1437281202847350784)]} 0 5
[junit4:junit4] 2> 2491843 T6975 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!13]} 0 9
[junit4:junit4] 2> 2491846 T6936 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1437281202855739392)]} 0 0
[junit4:junit4] 2> 2491855 T7006 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1437281202860982272)]} 0 0
[junit4:junit4] 2> 2491857 T6977 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!14 (1437281202860982272)]} 0 6
[junit4:junit4] 2> 2491861 T6937 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15 (1437281202871468032)]} 0 1
[junit4:junit4] 2> 2491872 T6988 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1437281202879856640)]} 0 0
[junit4:junit4] 2> 2491874 T6961 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!15 (1437281202879856640)]} 0 5
[junit4:junit4] 2> 2491875 T6973 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!15]} 0 10
[junit4:junit4] 2> 2491880 T6939 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1437281202891390976)]} 0 1
[junit4:junit4] 2> 2491888 T6989 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1437281202896633856)]} 0 1
[junit4:junit4] 2> 2491890 T6957 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!16 (1437281202896633856)]} 0 6
[junit4:junit4] 2> 2491895 T6938 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17 (1437281202905022464)]} 0 2
[junit4:junit4] 2> 2491904 T7007 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1437281202913411072)]} 0 0
[junit4:junit4] 2> 2491905 T6976 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!17 (1437281202913411072)]} 0 4
[junit4:junit4] 2> 2491907 T6956 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!17]} 0 9
[junit4:junit4] 2> 2491912 T6940 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1437281202924945408)]} 0 1
[junit4:junit4] 2> 2491921 T6990 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1437281202930188288)]} 0 1
[junit4:junit4] 2> 2491923 T6959 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!18 (1437281202930188288)]} 0 6
[junit4:junit4] 2> 2491927 T6941 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1437281202940674048)]} 0 0
[junit4:junit4] 2> 2491934 T6991 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1437281202943819776)]} 0 0
[junit4:junit4] 2> 2491936 T6960 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!19 (1437281202943819776)]} 0 6
[junit4:junit4] 2> 2491940 T6936 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1437281202954305536)]} 0 1
[junit4:junit4] 2> 2491948 T7008 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1437281202959548416)]} 0 1
[junit4:junit4] 2> 2491949 T6972 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!20 (1437281202959548416)]} 0 6
[junit4:junit4] 2> 2491953 T6937 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21 (1437281202967937024)]} 0 1
[junit4:junit4] 2> 2491962 T6992 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1437281202974228480)]} 0 1
[junit4:junit4] 2> 2491964 T6958 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!21 (1437281202974228480)]} 0 5
[junit4:junit4] 2> 2491965 T6974 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!21]} 0 9
[junit4:junit4] 2> 2491970 T6939 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1437281202985762816)]} 0 1
[junit4:junit4] 2> 2491978 T6993 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1437281202988908544)]} 0 0
[junit4:junit4] 2> 2491980 T6961 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!22 (1437281202988908544)]} 0 7
[junit4:junit4] 2> 2491984 T6938 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23 (1437281202999394304)]} 0 1
[junit4:junit4] 2> 2491993 T7009 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1437281203005685760)]} 0 1
[junit4:junit4] 2> 2491994 T6975 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!23 (1437281203005685760)]} 0 5
[junit4:junit4] 2> 2491996 T6957 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!23]} 0 9
[junit4:junit4] 2> 2492001 T6940 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24 (1437281203018268672)]} 0 1
[junit4:junit4] 2> 2492013 T7010 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1437281203026657280)]} 0 0
[junit4:junit4] 2> 2492014 T6977 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!24 (1437281203026657280)]} 0 5
[junit4:junit4] 2> 2492016 T6959 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!24]} 0 12
[junit4:junit4] 2> 2492019 T6936 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25 (1437281203037143040)]} 0 1
[junit4:junit4] 2> 2492029 T6988 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1437281203043434496)]} 0 1
[junit4:junit4] 2> 2492031 T6960 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!25 (1437281203043434496)]} 0 6
[junit4:junit4] 2> 2492032 T6976 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!25]} 0 9
[junit4:junit4] 2> 2492037 T6937 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1437281203054968832)]} 0 1
[junit4:junit4] 2> 2492044 T7006 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1437281203059163136)]} 0 1
[junit4:junit4] 2> 2492045 T6972 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!26 (1437281203059163136)]} 0 5
[junit4:junit4] 2> 2492048 T6939 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1437281203067551744)]} 0 0
[junit4:junit4] 2> 2492057 T6990 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1437281203071746048)]} 0 1
[junit4:junit4] 2> 2492059 T6958 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!27 (1437281203071746048)]} 0 7
[junit4:junit4] 2> 2492063 T6938 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1437281203082231808)]} 0 1
[junit4:junit4] 2> 2492070 T6991 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1437281203086426112)]} 0 1
[junit4:junit4] 2> 2492072 T6961 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!28 (1437281203086426112)]} 0 6
[junit4:junit4] 2> 2492076 T6940 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29 (1437281203096911872)]} 0 0
[junit4:junit4] 2> 2492087 T7007 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1437281203104251904)]} 0 1
[junit4:junit4] 2> 2492088 T6974 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!29 (1437281203104251904)]} 0 5
[junit4:junit4] 2> 2492090 T6957 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!29]} 0 11
[junit4:junit4] 2> 2492093 T6941 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30 (1437281203114737664)]} 0 0
[junit4:junit4] 2> 2492105 T7008 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1437281203123126272)]} 0 1
[junit4:junit4] 2> 2492105 T6975 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!30 (1437281203123126272)]} 0 4
[junit4:junit4] 2> 2492107 T6956 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!30]} 0 10
[junit4:junit4] 2> 2492110 T6936 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1437281203132563456)]} 0 0
[junit4:junit4] 2> 2492118 T7009 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1437281203136757760)]} 0 1
[junit4:junit4] 2> 2492120 T6973 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!31 (1437281203136757760)]} 0 6
[junit4:junit4] 2> 2492124 T6937 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1437281203146194944)]} 0 1
[junit4:junit4] 2> 2492131 T6992 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1437281203150389248)]} 0 0
[junit4:junit4] 2> 2492134 T6959 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!32 (1437281203150389248)]} 0 7
[junit4:junit4] 2> 2492138 T6939 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1437281203160875008)]} 0 1
[junit4:junit4] 2> 2492142 T6993 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1437281203164020736)]} 0 0
[junit4:junit4] 2> 2492143 T6960 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!33 (1437281203164020736)]} 0 3
[junit4:junit4] 2> 2492145 T6938 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1437281203169263616)]} 0 0
[junit4:junit4] 2> 2492150 T6989 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1437281203172409344)]} 0 0
[junit4:junit4] 2> 2492151 T6958 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!34 (1437281203172409344)]} 0 3
[junit4:junit4] 2> 2492155 T6940 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35 (1437281203179749376)]} 0 0
[junit4:junit4] 2> 2492164 T6988 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1437281203186040832)]} 0 1
[junit4:junit4] 2> 2492166 T6961 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!35 (1437281203186040832)]} 0 5
[junit4:junit4] 2> 2492168 T6977 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!35]} 0 10
[junit4:junit4] 2> 2492172 T6941 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36 (1437281203196526592)]} 0 1
[junit4:junit4] 2> 2492183 T6990 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1437281203204915200)]} 0 1
[junit4:junit4] 2> 2492184 T6957 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!36 (1437281203204915200)]} 0 5
[junit4:junit4] 2> 2492186 T6976 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!36]} 0 11
[junit4:junit4] 2> 2492190 T6936 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1437281203216449536)]} 0 1
[junit4:junit4] 2> 2492197 T7005 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1437281203219595264)]} 0 1
[junit4:junit4] 2> 2492198 T6972 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!37 (1437281203219595264)]} 0 5
[junit4:junit4] 2> 2492202 T6937 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1437281203229032448)]} 0 0
[junit4:junit4] 2> 2492211 T7010 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1437281203234275328)]} 0 1
[junit4:junit4] 2> 2492212 T6974 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!38 (1437281203234275328)]} 0 5
[junit4:junit4] 2> 2492216 T6939 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39 (1437281203243712512)]} 0 0
[junit4:junit4] 2> 2492227 T6991 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1437281203251052544)]} 0 0
[junit4:junit4] 2> 2492228 T6956 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!39 (1437281203251052544)]} 0 5
[junit4:junit4] 2> 2492230 T6975 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!39]} 0 9
[junit4:junit4] 2> 2492234 T6938 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1437281203261538304)]} 0 1
[junit4:junit4] 2> 2492242 T7006 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1437281203265732608)]} 0 1
[junit4:junit4] 2> 2492243 T6973 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[o!40 (1437281203265732608)]} 0 6
[junit4:junit4] 2> 2492247 T6940 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41 (1437281203276218368)]} 0 1
[junit4:junit4] 2> 2492256 T6992 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1437281203282509824)]} 0 1
[junit4:junit4] 2> 2492258 T6959 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!41 (1437281203282509824)]} 0 5
[junit4:junit4] 2> 2492259 T6977 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[p!41]} 0 9
[junit4:junit4] 2> 2492264 T6941 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1437281203292995584)]} 0 1
[junit4:junit4] 2> 2492272 T6993 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1437281203297189888)]} 0 1
[junit4:junit4] 2> 2492274 T6960 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[q!42 (1437281203297189888)]} 0 7
[junit4:junit4] 2> 2492277 T6936 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1437281203307675648)]} 0 0
[junit4:junit4] 2> 2492285 T7007 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1437281203311869952)]} 0 1
[junit4:junit4] 2> 2492286 T6976 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[r!43 (1437281203311869952)]} 0 6
[junit4:junit4] 2> 2492290 T6937 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1437281203321307136)]} 0 1
[junit4:junit4] 2> 2492298 T6989 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1437281203324452864)]} 0 1
[junit4:junit4] 2> 2492300 T6958 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[s!44 (1437281203324452864)]} 0 7
[junit4:junit4] 2> 2492303 T6939 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45 (1437281203334938624)]} 0 0
[junit4:junit4] 2> 2492314 T6988 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1437281203342278656)]} 0 1
[junit4:junit4] 2> 2492316 T6961 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!45 (1437281203342278656)]} 0 6
[junit4:junit4] 2> 2492317 T6972 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[t!45]} 0 9
[junit4:junit4] 2> 2492321 T6938 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1437281203353812992)]} 0 0
[junit4:junit4] 2> 2492329 T7008 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1437281203358007296)]} 0 1
[junit4:junit4] 2> 2492345 T6974 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[u!46 (1437281203358007296)]} 0 20
[junit4:junit4] 2> 2492348 T6940 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47 (1437281203382124544)]} 0 0
[junit4:junit4] 2> 2492360 T6990 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1437281203391561728)]} 0 1
[junit4:junit4] 2> 2492361 T6957 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!47 (1437281203391561728)]} 0 5
[junit4:junit4] 2> 2492363 T6975 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[v!47]} 0 10
[junit4:junit4] 2> 2492367 T6941 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1437281203402047488)]} 0 0
[junit4:junit4] 2> 2492376 T6991 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1437281203406241792)]} 0 1
[junit4:junit4] 2> 2492377 T6956 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[w!48 (1437281203406241792)]} 0 6
[junit4:junit4] 2> 2492381 T6936 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1437281203416727552)]} 0 1
[junit4:junit4] 2> 2492388 T7009 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1437281203420921856)]} 0 0
[junit4:junit4] 2> 2492390 T6973 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[x!49 (1437281203420921856)]} 0 6
[junit4:junit4] 2> 2492395 T6937 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1437281203431407616)]} 0 0
[junit4:junit4] 2> 2492403 T7005 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1437281203435601920)]} 0 1
[junit4:junit4] 2> 2492405 T6977 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[y!50 (1437281203435601920)]} 0 6
[junit4:junit4] 2> 2492408 T6939 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1437281203445039104)]} 0 0
[junit4:junit4] 2> 2492417 T6992 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1437281203449233408)]} 0 1
[junit4:junit4] 2> 2492418 T6959 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[z!51 (1437281203449233408)]} 0 6
[junit4:junit4] 2> 2492423 T6940 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52 (1437281203460767744)]} 0 1
[junit4:junit4] 2> 2492432 T7010 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1437281203467059200)]} 0 0
[junit4:junit4] 2> 2492434 T6976 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!52 (1437281203467059200)]} 0 6
[junit4:junit4] 2> 2492436 T6958 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[a!52]} 0 11
[junit4:junit4] 2> 2492440 T6941 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1437281203478593536)]} 0 1
[junit4:junit4] 2> 2492447 T6993 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1437281203481739264)]} 0 1
[junit4:junit4] 2> 2492449 T6961 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[b!53 (1437281203481739264)]} 0 6
[junit4:junit4] 2> 2492452 T6936 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54 (1437281203491176448)]} 0 0
[junit4:junit4] 2> 2492462 T6988 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1437281203497467904)]} 0 1
[junit4:junit4] 2> 2492463 T6957 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!54 (1437281203497467904)]} 0 5
[junit4:junit4] 2> 2492465 T6974 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[c!54]} 0 10
[junit4:junit4] 2> 2492470 T6937 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55 (1437281203510050816)]} 0 1
[junit4:junit4] 2> 2492480 T7007 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1437281203517390848)]} 0 1
[junit4:junit4] 2> 2492481 T6975 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!55 (1437281203517390848)]} 0 5
[junit4:junit4] 2> 2492483 T6956 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[d!55]} 0 10
[junit4:junit4] 2> 2492486 T6938 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56 (1437281203526828032)]} 0 0
[junit4:junit4] 2> 2492497 T7008 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1437281203535216640)]} 0 1
[junit4:junit4] 2> 2492499 T6973 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!56 (1437281203535216640)]} 0 6
[junit4:junit4] 2> 2492500 T6960 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[e!56]} 0 11
[junit4:junit4] 2> 2492504 T6939 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1437281203545702400)]} 0 1
[junit4:junit4] 2> 2492511 T7009 C6652 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1437281203549896704)]} 0 1
[junit4:junit4] 2> 2492512 T6977 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[f!57 (1437281203549896704)]} 0 5
[junit4:junit4] 2> 2492514 T6940 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58 (1437281203556188160)]} 0 0
[junit4:junit4] 2> 2492526 T6990 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1437281203565625344)]} 0 1
[junit4:junit4] 2> 2492527 T6959 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!58 (1437281203565625344)]} 0 4
[junit4:junit4] 2> 2492529 T6972 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[g!58]} 0 11
[junit4:junit4] 2> 2492533 T6941 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59 (1437281203575062528)]} 0 1
[junit4:junit4] 2> 2492543 T6991 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1437281203584499712)]} 0 1
[junit4:junit4] 2> 2492544 T6958 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!59 (1437281203584499712)]} 0 4
[junit4:junit4] 2> 2492546 T6976 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[h!59]} 0 9
[junit4:junit4] 2> 2492551 T6936 C6654 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60 (1437281203592888320)]} 0 2
[junit4:junit4] 2> 2492561 T6992 C6650 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1437281203602325504)]} 0 1
[junit4:junit4] 2> 2492562 T6961 C6651 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!60 (1437281203602325504)]} 0 4
[junit4:junit4] 2> 2492564 T6974 C6653 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[i!60]} 0 10
[junit4:junit4] 2> ASYNC NEW_CORE C6655 name=collection1 org.apache.solr.core.SolrCore@153e3a3 url=http://127.0.0.1:50281/collection1 node=127.0.0.1:50281_ C6655_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:50281_, base_url=http://127.0.0.1:50281, leader=true}
[junit4:junit4] 2> 2492587 T6937 C6655 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61 (1437281203632734208)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C6656 name=collection1 org.apache.solr.core.SolrCore@fe7370 url=http://127.0.0.1:50311/collection1 node=127.0.0.1:50311_ C6656_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50311_, base_url=http://127.0.0.1:50311}
[junit4:junit4] 2> 2492599 T6989 C6656 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1437281203642171392)]} 0 1
[junit4:junit4] 2> ASYNC NEW_CORE C6657 name=collection1 org.apache.solr.core.SolrCore@1d22cfb url=http://127.0.0.1:50293/collection1 node=127.0.0.1:50293_ C6657_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50293_, base_url=http://127.0.0.1:50293, leader=true}
[junit4:junit4] 2> 2492600 T6957 C6657 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!61 (1437281203642171392)]} 0 5
[junit4:junit4] 2> ASYNC NEW_CORE C6658 name=collection1 org.apache.solr.core.SolrCore@361f00 url=http://127.0.0.1:50302/collection1 node=127.0.0.1:50302_ C6658_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50302_, base_url=http://127.0.0.1:50302, leader=true}
[junit4:junit4] 2> 2492602 T6975 C6658 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[j!61]} 0 10
[junit4:junit4] 2> 2492605 T6938 C6655 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62 (1437281203651608576)]} 0 0
[junit4:junit4] 2> 2492614 T6993 C6656 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!62 (1437281203657900032)]} 0 0
[junit4:junit4] 2> 2492616 T6956 C6657 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[k!62 (1437281203657900032)]} 0 6
[junit4:junit4] 2> 2492621 T6939 C6655 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63 (1437281203668385792)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C6659 name=collection1 org.apache.solr.core.SolrCore@119c6e0 url=http://127.0.0.1:50321/collection1 node=127.0.0.1:50321_ C6659_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50321_, base_url=http://127.0.0.1:50321}
[junit4:junit4] 2> 2492631 T7005 C6659 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!63 (1437281203676774400)]} 0 1
[junit4:junit4] 2> 2492632 T6973 C6658 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!63 (1437281203676774400)]} 0 4
[junit4:junit4] 2> 2492635 T6960 C6657 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[l!63]} 0 10
[junit4:junit4] 2> 2492639 T6940 C6655 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!64 (1437281203687260160)]} 0 1
[junit4:junit4] 2> 2492649 T7006 C6659 P50321 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50302/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!64 (1437281203694600192)]} 0 1
[junit4:junit4] 2> 2492650 T6977 C6658 P50302 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!64 (1437281203694600192)]} 0 5
[junit4:junit4] 2> 2492651 T6959 C6657 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[m!64]} 0 9
[junit4:junit4] 2> 2492654 T6941 C6655 P50281 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[n!65 (1437281203702988800)]} 0 0
[junit4:junit4] 2> 2492660 T6988 C6656 P50311 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50293/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!65 (1437281203707183104)]} 0 0
[junit4:junit4] 2> 2492661 T6958 C6657 P50293 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/upda
[...truncated too long message...]
:junit4] 2> 2528435 T6923 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:50274 50274
[junit4:junit4] 2> 2529603 T7014 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2530686 T7014 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> 2530687 T7014 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2530690 T6923 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 50281
[junit4:junit4] 2> 2530712 T6923 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 2530713 T6923 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:50274 50274
[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=8D3F349626E11ACA -Dtests.slow=true -Dtests.locale=sq_AL -Dtests.timezone=BST -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR 67.9s | ShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:50293 returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([8D3F349626E11ACA:CD9BA8E51BE7AF6]: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:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 2530730 T6923 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=PostingsFormat(name=Lucene41WithOrds), _version_=Pulsing41(freqCutoff=13 minBlockSize=17 maxBlockSize=78), n_ti=Pulsing41(freqCutoff=13 minBlockSize=17 maxBlockSize=78)}, docValues:{}, sim=DefaultSimilarity, locale=sq_AL, timezone=BST
[junit4:junit4] 2> NOTE: Windows 7 6.1 x86/Oracle Corporation 1.7.0_21 (32-bit)/cpus=2,threads=2,free=223819552,total=333037568
[junit4:junit4] 2> NOTE: All tests run in this JVM: [BasicDistributedZkTest, JSONWriterTest, UpdateRequestProcessorFactoryTest, TestShardHandlerFactory, XmlUpdateRequestHandlerTest, TestLFUCache, LegacyHTMLStripCharFilterTest, LeaderElectionTest, TermVectorComponentDistributedTest, TestSerializedLuceneMatchVersion, PolyFieldTest, XsltUpdateRequestHandlerTest, HighlighterConfigTest, TestJmxMonitoredMap, FieldAnalysisRequestHandlerTest, TestConfig, ConvertedLegacyTest, TestUniqueKeyFieldResource, TestDefaultSearchFieldResource, NotRequiredUniqueKeyTest, DirectUpdateHandlerTest, HighlighterTest, TestDFRSimilarityFactory, SuggesterWFSTTest, TestHashPartitioner, PluginInfoTest, PeerSyncTest, BasicDistributedZk2Test, TestPHPSerializedResponseWriter, TestMergePolicyConfig, TestDistributedGrouping, TestPseudoReturnFields, TestGroupingSearch, AutoCommitTest, SuggesterTest, TestStressVersions, SpellingQueryConverterTest, NoCacheHeaderTest, TestWordDelimiterFilterFactory, TestFieldCollectionResource, TestMaxScoreQueryParser, OpenExchangeRatesOrgProviderTest, BasicZkTest, TestBinaryField, TestDefaultSimilarityFactory, TestXIncludeConfig, HardAutoCommitTest, TestReload, SyncSliceTest, BasicFunctionalityTest, AnalysisAfterCoreReloadTest, UUIDFieldTest, SampleTest, TestExtendedDismaxParser, DocumentBuilderTest, TestArbitraryIndexDir, IndexBasedSpellCheckerTest, MinimalSchemaTest, TestLMDirichletSimilarityFactory, TermsComponentTest, SignatureUpdateProcessorFactoryTest, ScriptEngineTest, ReturnFieldsTest, TestSolrQueryParser, ShardRoutingCustomTest, TestRandomDVFaceting, TestRealTimeGet, DocValuesTest, CurrencyFieldOpenExchangeTest, StandardRequestHandlerTest, RequiredFieldsTest, DebugComponentTest, TestMultiCoreConfBootstrap, DOMUtilTest, PreAnalyzedUpdateProcessorTest, SolrCoreCheckLockOnStartupTest, TestLRUCache, SpellPossibilityIteratorTest, TestManagedSchemaFieldResource, CurrencyFieldXmlFileTest, SortByFunctionTest, TestIBSimilarityFactory, TestUpdate, QueryResultKeyTest, ShowFileRequestHandlerTest, PathHierarchyTokenizerFactoryTest, CacheHeaderTest, SimpleFacetsTest, TestPropInjectDefaults, TestSolrIndexConfig, TestBM25SimilarityFactory, TestRTGBase, ZkControllerTest, TestDynamicFieldCollectionResource, TestCSVLoader, TestReloadAndDeleteDocs, ZkNodePropsTest, DocumentAnalysisRequestHandlerTest, TestStressRecovery, QueryParsingTest, OutputWriterTest, TestReplicationHandler, SuggesterFSTTest, TestTrie, AlternateDirectoryTest, OverseerTest, ZkSolrClientTest, PingRequestHandlerTest, ResponseLogComponentTest, PrimUtilsTest, TestReversedWildcardFilterFactory, TestPartialUpdateDeduplication, SpatialFilterTest, DistributedTermsComponentTest, SpellCheckComponentTest, MBeansHandlerTest, TestAtomicUpdateErrorCases, CoreContainerCoreInitFailuresTest, ExternalFileFieldSortTest, IndexSchemaRuntimeFieldTest, SolrInfoMBeanTest, LukeRequestHandlerTest, UnloadDistributedZkTest, FileBasedSpellCheckerTest, CSVRequestHandlerTest, TestSolr4Spatial, CoreAdminHandlerTest, StatelessScriptUpdateProcessorFactoryTest, TestDistributedSearch, TestFastWriter, TestSolrDeletionPolicy2, RequestHandlersTest, DistributedQueryElevationComponentTest, TestSuggestSpellingConverter, IndexReaderFactoryTest, TestQuerySenderNoQuery, TestStressReorder, OpenCloseCoreStressTest, UniqFieldsUpdateProcessorFactoryTest, ClusterStateUpdateTest, TestStressLucene, ChaosMonkeySafeLeaderTest, CollectionsAPIDistributedZkTest, LeaderElectionIntegrationTest, ShardRoutingTest, RecoveryZkTest, FullSolrCloudDistribCmdsTest, TestRandomFaceting, TestZkChroot, ZkCLITest, SliceStateUpdateTest, TestFaceting, TestRecovery, DistributedSpellCheckComponentTest, TestJoin, TestRangeQuery, TestCoreContainer, SolrCoreTest, StatsComponentTest, SolrCmdDistributorTest, QueryElevationComponentTest, BadIndexSchemaTest, TestSort, TestFiltering, TestFunctionQuery, TestLazyCores, TestBadConfig, OverseerCollectionProcessorTest, TestIndexSearcher, SoftAutoCommitTest, SolrIndexSplitterTest, SimplePostToolTest, TestCoreDiscovery, SpellCheckCollatorTest, SolrRequestParserTest, TestFoldingMultitermQuery, SuggesterTSTTest, WordBreakSolrSpellCheckerTest, SchemaVersionSpecificBehaviorTest, FieldMutatingUpdateProcessorTest, QueryEqualityTest, DirectUpdateHandlerOptimizeTest, DefaultValueUpdateProcessorTest, TestRemoteStreaming, DocValuesMultiTest, DistanceFunctionTest, TestSolrDeletionPolicy1, TestSurroundQueryParser, DisMaxRequestHandlerTest, TestQueryUtils, TestWriterPerf, DirectSolrSpellCheckerTest, TestQueryTypes, PrimitiveFieldTypeTest, TestOmitPositions, TestValueSourceCache, TermVectorComponentTest, TestIndexingPerformance, MoreLikeThisHandlerTest, FastVectorHighlighterTest, LoggingHandlerTest, RegexBoostProcessorTest, SolrPluginUtilsTest, IndexSchemaTest, TestJmxIntegration, TestCollationField, TestCSVResponseWriter, TestAnalyzedSuggestions, JsonLoaderTest, BinaryUpdateRequestHandlerTest, TestComponentsName, SearchHandlerTest, TestBinaryResponseWriter, SOLR749Test, TestPropInject, TestQuerySenderListener, UpdateParamsTest, CopyFieldTest, SolrIndexConfigTest, BadComponentTest, MultiTermTest, TestDocSet, TestSearchPerf, NumericFieldsTest, TestElisionMultitermQuery, TestFuzzyAnalyzedSuggestions, TestSolrCoreProperties, TestPostingsSolrHighlighter, DirectSolrConnectionTest, TestLuceneMatchVersion, TestPhraseSuggestions, TestCharFilters, TestCodecSupport, SynonymTokenizerTest, EchoParamsTest, TestSweetSpotSimilarityFactory, TestPerFieldSimilarity, TestNumberUtils, TestLMJelinekMercerSimilarityFactory, TestPluginEnable, TimeZoneUtilsTest, ResourceLoaderTest, TestFastOutputStream, URLClassifyProcessorTest, TestFastLRUCache, DateMathParserTest, ChaosMonkeyNothingIsSafeTest, TestSolrXMLSerializer, PreAnalyzedFieldTest, TestSystemIdResolver, DateFieldTest, RAMDirectoryFactoryTest, ClusterStateTest, TestSolrJ, TestUtils, TestDocumentBuilder, SliceStateTest, SystemInfoHandlerTest, FileUtilsTest, CircularListTest, SolrTestCaseJ4Test, TestCollationKeyRangeQueries, AliasIntegrationTest, ChaosMonkeyShardSplitTest, ShardSplitTest]
[junit4:junit4] Completed in 67.94s, 1 test, 1 error <<< FAILURES!
[...truncated 66 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:391: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:371: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\build.xml:181: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\solr\common-build.xml:437: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\lucene\common-build.xml:1243: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-4.x-Windows\lucene\common-build.xml:887: There were test failures: 297 suites, 1246 tests, 1 error, 18 ignored (12 assumptions)
Total time: 66 minutes 13 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_21 -client -XX:+UseConcMarkSweepGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure