You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/05/29 06:27:20 UTC
[JENKINS] Lucene-Solr-trunk-Windows (32bit/jdk1.7.0_21) - Build #
2873 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Windows/2873/
Java: 32bit/jdk1.7.0_21 -client -XX:+UseSerialGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:50389/e_fd 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:50389/e_fd returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([5C186D28EE33AF39:DDFEE330996CCF05]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:133)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.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 9485 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 1179115 T3414 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /e_fd/
[junit4:junit4] 2> 1179119 T3414 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\solrtest-ShardSplitTest-1369800251048
[junit4:junit4] 2> 1179120 T3414 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1179121 T3415 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1179214 T3414 oasc.ZkTestServer.run start zk server on port:50370
[junit4:junit4] 2> 1179215 T3414 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1179233 T3421 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@36fe23 name:ZooKeeperConnection Watcher:127.0.0.1:50370 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1179233 T3414 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1179234 T3414 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1179248 T3416 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eee7516b20000, 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> 1179252 T3414 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1179258 T3423 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8f70e7 name:ZooKeeperConnection Watcher:127.0.0.1:50370/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1179258 T3414 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1179259 T3414 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1179273 T3414 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1179282 T3414 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1179290 T3414 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1179300 T3414 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1179302 T3414 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1179320 T3414 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 1179321 T3414 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1179331 T3414 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1179332 T3414 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1179343 T3414 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 1179345 T3414 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1179360 T3414 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 1179361 T3414 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1179373 T3414 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1179374 T3414 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1179385 T3414 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1179386 T3414 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1179396 T3414 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1179398 T3414 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1179407 T3414 oasc.AbstractZkTestCase.putConfig put C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test-files\solr\collection1\conf\synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1179408 T3414 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1179426 T3416 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eee7516b20001, 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> 1179837 T3414 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1179844 T3414 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50377
[junit4:junit4] 2> 1179844 T3414 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1179845 T3414 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1179845 T3414 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1369800251354
[junit4:junit4] 2> 1179845 T3414 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1369800251354\solr.xml
[junit4:junit4] 2> 1179846 T3414 oasc.CoreContainer.<init> New CoreContainer 14112371
[junit4:junit4] 2> 1179846 T3414 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1369800251354\'
[junit4:junit4] 2> 1179847 T3414 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1369800251354\'
[junit4:junit4] 2> 1179958 T3414 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1179959 T3414 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1179959 T3414 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1179959 T3414 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1179960 T3414 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1179960 T3414 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1179961 T3414 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1179961 T3414 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1179961 T3414 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1179962 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1179970 T3414 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1179971 T3414 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50370/solr
[junit4:junit4] 2> 1179971 T3414 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1179973 T3414 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1179987 T3434 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7c392 name:ZooKeeperConnection Watcher:127.0.0.1:50370 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1179988 T3414 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1179993 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1180005 T3414 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1180010 T3436 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@10a469d name:ZooKeeperConnection Watcher:127.0.0.1:50370/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1180010 T3414 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1180013 T3414 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1180020 T3414 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1180026 T3414 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1180030 T3414 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50377_e_fd
[junit4:junit4] 2> 1180033 T3414 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50377_e_fd
[junit4:junit4] 2> 1180039 T3414 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1180049 T3414 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1180052 T3414 oasc.Overseer.start Overseer (id=89771229253337091-127.0.0.1:50377_e_fd-n_0000000000) starting
[junit4:junit4] 2> 1180062 T3414 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1180074 T3438 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1180076 T3414 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1180080 T3414 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1180084 T3414 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1180088 T3437 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1180092 T3439 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1369800251354\collection1
[junit4:junit4] 2> 1180092 T3439 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1180093 T3439 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1180094 T3439 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1180096 T3439 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1369800251354\collection1\'
[junit4:junit4] 2> 1180097 T3439 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1369800251354/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1180098 T3439 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1369800251354/collection1/lib/README' to classloader
[junit4:junit4] 2> 1180149 T3439 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1180222 T3439 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1180224 T3439 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1180231 T3439 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1180830 T3439 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1180834 T3439 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1180835 T3439 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1180841 T3439 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1180877 T3439 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1180877 T3439 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-controljetty-1369800251354\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1369800251047/control/data\
[junit4:junit4] 2> 1180877 T3439 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@177a9ff
[junit4:junit4] 2> 1180878 T3439 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1180878 T3439 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369800251047/control/data\
[junit4:junit4] 2> 1180879 T3439 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1369800251047/control/data\index/
[junit4:junit4] 2> 1180879 T3439 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1369800251047\control\data\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1180879 T3439 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369800251047/control/data\index
[junit4:junit4] 2> 1180884 T3439 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d5acc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e9b364),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1180884 T3439 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1180889 T3439 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1180890 T3439 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1180890 T3439 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1180898 T3439 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1180899 T3439 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1180899 T3439 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1180900 T3439 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1180900 T3439 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1180901 T3439 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1180911 T3439 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1180917 T3439 oass.SolrIndexSearcher.<init> Opening Searcher@120c2de main
[junit4:junit4] 2> 1180917 T3439 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1369800251047\control\data\tlog
[junit4:junit4] 2> 1180919 T3439 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1180919 T3439 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1180923 T3440 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@120c2de main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1180924 T3439 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1180924 T3439 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1181442 T3437 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1181444 T3437 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:50377_e_fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50377/e_fd"}
[junit4:junit4] 2> 1181445 T3437 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1181445 T3437 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1181464 T3436 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> 1181773 T3439 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1181773 T3439 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50377/e_fd collection:control_collection shard:shard1
[junit4:junit4] 2> 1181775 T3439 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1181801 T3439 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1181811 T3439 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1181812 T3439 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1181812 T3439 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50377/e_fd/collection1/
[junit4:junit4] 2> 1181812 T3439 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1181812 T3439 oasc.SyncStrategy.syncToMe http://127.0.0.1:50377/e_fd/collection1/ has no replicas
[junit4:junit4] 2> 1181813 T3439 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50377/e_fd/collection1/
[junit4:junit4] 2> 1181813 T3439 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1182727 T3437 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1182756 T3436 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> 1182772 T3439 oasc.ZkController.register We are http://127.0.0.1:50377/e_fd/collection1/ and leader is http://127.0.0.1:50377/e_fd/collection1/
[junit4:junit4] 2> 1182772 T3439 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50377/e_fd
[junit4:junit4] 2> 1182773 T3439 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1182773 T3439 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1182773 T3439 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1182778 T3439 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1182781 T3414 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 1182781 T3414 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1182783 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1182797 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1182799 T3414 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1182803 T3443 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5b63c2 name:ZooKeeperConnection Watcher:127.0.0.1:50370/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1182803 T3414 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1182804 T3414 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1182808 T3414 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1183153 T3414 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1183157 T3414 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50389
[junit4:junit4] 2> 1183157 T3414 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1183158 T3414 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1183158 T3414 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1369800254736
[junit4:junit4] 2> 1183158 T3414 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1369800254736\solr.xml
[junit4:junit4] 2> 1183159 T3414 oasc.CoreContainer.<init> New CoreContainer 4571887
[junit4:junit4] 2> 1183160 T3414 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1369800254736\'
[junit4:junit4] 2> 1183160 T3414 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1369800254736\'
[junit4:junit4] 2> 1183251 T3414 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1183251 T3414 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1183251 T3414 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1183251 T3414 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1183251 T3414 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1183252 T3414 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1183252 T3414 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1183253 T3414 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1183253 T3414 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1183253 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1183260 T3414 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1183260 T3414 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50370/solr
[junit4:junit4] 2> 1183261 T3414 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1183262 T3414 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1183275 T3454 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@119a51f name:ZooKeeperConnection Watcher:127.0.0.1:50370 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1183276 T3414 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1183279 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1183286 T3414 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1183289 T3456 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@18872a3 name:ZooKeeperConnection Watcher:127.0.0.1:50370/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1183290 T3414 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1183298 T3414 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1184025 T3437 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1184027 T3437 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50377_e_fd_collection1",
[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:50377_e_fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50377/e_fd"}
[junit4:junit4] 2> 1184044 T3443 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> 1184046 T3436 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> 1184047 T3456 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> 1184137 T3414 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50389_e_fd
[junit4:junit4] 2> 1184143 T3414 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50389_e_fd
[junit4:junit4] 2> 1184149 T3443 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> 1184150 T3436 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> 1184153 T3456 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1184154 T3456 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> 1184157 T3443 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1184158 T3436 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1184169 T3457 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1369800254736\collection1
[junit4:junit4] 2> 1184169 T3457 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1184169 T3457 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1184169 T3457 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1184172 T3457 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1369800254736\collection1\'
[junit4:junit4] 2> 1184173 T3457 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1369800254736/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1184174 T3457 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1369800254736/collection1/lib/README' to classloader
[junit4:junit4] 2> 1184237 T3457 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1184293 T3457 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1184296 T3457 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1184301 T3457 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1184850 T3457 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1184853 T3457 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1184854 T3457 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1184860 T3457 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1184886 T3457 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1184886 T3457 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty1-1369800254736\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty1\
[junit4:junit4] 2> 1184887 T3457 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@177a9ff
[junit4:junit4] 2> 1184887 T3457 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1184887 T3457 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty1\
[junit4:junit4] 2> 1184887 T3457 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty1\index/
[junit4:junit4] 2> 1184887 T3457 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1369800251047\jetty1\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1184888 T3457 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty1\index
[junit4:junit4] 2> 1184892 T3457 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1cde652 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16baa67),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1184892 T3457 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1184896 T3457 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1184896 T3457 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1184896 T3457 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1184897 T3457 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1184897 T3457 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1184898 T3457 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1184898 T3457 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1184898 T3457 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1184899 T3457 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1184908 T3457 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1184914 T3457 oass.SolrIndexSearcher.<init> Opening Searcher@1bb005a main
[junit4:junit4] 2> 1184914 T3457 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1369800251047\jetty1\tlog
[junit4:junit4] 2> 1184914 T3457 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1184914 T3457 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1184919 T3458 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1bb005a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1184921 T3457 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1184921 T3457 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1185312 T3437 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1185314 T3437 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:50389_e_fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50389/e_fd"}
[junit4:junit4] 2> 1185314 T3437 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 1185315 T3437 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1185332 T3443 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> 1185332 T3436 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> 1185333 T3456 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> 1185758 T3457 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1185759 T3457 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50389/e_fd collection:collection1 shard:shard1
[junit4:junit4] 2> 1185759 T3457 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 1185789 T3457 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1185798 T3457 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1185798 T3457 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1185799 T3457 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50389/e_fd/collection1/
[junit4:junit4] 2> 1185799 T3457 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1185799 T3457 oasc.SyncStrategy.syncToMe http://127.0.0.1:50389/e_fd/collection1/ has no replicas
[junit4:junit4] 2> 1185799 T3457 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50389/e_fd/collection1/
[junit4:junit4] 2> 1185800 T3457 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1186597 T3437 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1186628 T3443 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> 1186628 T3436 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> 1186629 T3456 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> 1186635 T3457 oasc.ZkController.register We are http://127.0.0.1:50389/e_fd/collection1/ and leader is http://127.0.0.1:50389/e_fd/collection1/
[junit4:junit4] 2> 1186635 T3457 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50389/e_fd
[junit4:junit4] 2> 1186636 T3457 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1186636 T3457 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1186637 T3457 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1186643 T3457 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1186648 T3414 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 1186649 T3414 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1186650 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1187013 T3414 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1187017 T3414 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50398
[junit4:junit4] 2> 1187017 T3414 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1187018 T3414 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1187018 T3414 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1369800258590
[junit4:junit4] 2> 1187019 T3414 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1369800258590\solr.xml
[junit4:junit4] 2> 1187019 T3414 oasc.CoreContainer.<init> New CoreContainer 18921037
[junit4:junit4] 2> 1187019 T3414 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1369800258590\'
[junit4:junit4] 2> 1187019 T3414 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1369800258590\'
[junit4:junit4] 2> 1187146 T3414 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1187147 T3414 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1187147 T3414 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1187147 T3414 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1187147 T3414 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1187148 T3414 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1187148 T3414 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1187148 T3414 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1187149 T3414 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1187149 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1187156 T3414 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1187156 T3414 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50370/solr
[junit4:junit4] 2> 1187157 T3414 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1187158 T3414 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1187169 T3470 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@f3bd2b name:ZooKeeperConnection Watcher:127.0.0.1:50370 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1187169 T3414 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1187173 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1187179 T3414 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1187182 T3472 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@64f7bd name:ZooKeeperConnection Watcher:127.0.0.1:50370/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1187182 T3414 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1187191 T3414 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1187902 T3437 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1187903 T3437 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50389_e_fd_collection1",
[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:50389_e_fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50389/e_fd"}
[junit4:junit4] 2> 1187912 T3443 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> 1187912 T3436 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> 1187912 T3456 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> 1187912 T3472 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> 1188028 T3414 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50398_e_fd
[junit4:junit4] 2> 1188031 T3414 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50398_e_fd
[junit4:junit4] 2> 1188034 T3443 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> 1188034 T3436 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> 1188034 T3472 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> 1188036 T3456 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1188036 T3456 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> 1188038 T3443 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1188039 T3472 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1188039 T3436 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1188046 T3473 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1369800258590\collection1
[junit4:junit4] 2> 1188046 T3473 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1188047 T3473 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1188047 T3473 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1188050 T3473 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1369800258590\collection1\'
[junit4:junit4] 2> 1188051 T3473 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1369800258590/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1188052 T3473 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1369800258590/collection1/lib/README' to classloader
[junit4:junit4] 2> 1188099 T3473 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1188169 T3473 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1188170 T3473 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1188175 T3473 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1188725 T3473 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1188729 T3473 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1188731 T3473 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1188737 T3473 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1188765 T3473 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1188765 T3473 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty2-1369800258590\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty2\
[junit4:junit4] 2> 1188765 T3473 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@177a9ff
[junit4:junit4] 2> 1188766 T3473 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1188766 T3473 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty2\
[junit4:junit4] 2> 1188767 T3473 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty2\index/
[junit4:junit4] 2> 1188767 T3473 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1369800251047\jetty2\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1188768 T3473 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty2\index
[junit4:junit4] 2> 1188772 T3473 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@120db6d lockFactory=org.apache.lucene.store.NativeFSLockFactory@a1bae7),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1188772 T3473 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1188775 T3473 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1188775 T3473 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1188776 T3473 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1188786 T3473 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1188787 T3473 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1188787 T3473 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1188788 T3473 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1188789 T3473 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1188790 T3473 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1188800 T3473 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1188806 T3473 oass.SolrIndexSearcher.<init> Opening Searcher@1099c8c main
[junit4:junit4] 2> 1188807 T3473 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1369800251047\jetty2\tlog
[junit4:junit4] 2> 1188808 T3473 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1188808 T3473 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1188815 T3474 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1099c8c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1188816 T3473 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1188817 T3473 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1189174 T3437 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1189176 T3437 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:50398_e_fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50398/e_fd"}
[junit4:junit4] 2> 1189177 T3437 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1189177 T3437 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1189194 T3443 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> 1189194 T3456 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> 1189195 T3472 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> 1189194 T3436 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> 1189630 T3473 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1189630 T3473 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50398/e_fd collection:collection1 shard:shard2
[junit4:junit4] 2> 1189632 T3473 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 1189659 T3473 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1189668 T3473 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1189669 T3473 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1189669 T3473 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50398/e_fd/collection1/
[junit4:junit4] 2> 1189670 T3473 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1189670 T3473 oasc.SyncStrategy.syncToMe http://127.0.0.1:50398/e_fd/collection1/ has no replicas
[junit4:junit4] 2> 1189671 T3473 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50398/e_fd/collection1/
[junit4:junit4] 2> 1189671 T3473 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1190354 T3437 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1190382 T3443 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> 1190383 T3472 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> 1190383 T3456 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> 1190383 T3436 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> 1190414 T3473 oasc.ZkController.register We are http://127.0.0.1:50398/e_fd/collection1/ and leader is http://127.0.0.1:50398/e_fd/collection1/
[junit4:junit4] 2> 1190414 T3473 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50398/e_fd
[junit4:junit4] 2> 1190414 T3473 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1190414 T3473 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1190415 T3473 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1190419 T3473 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1190422 T3414 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 1190422 T3414 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1190424 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1190747 T3414 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1190751 T3414 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50407
[junit4:junit4] 2> 1190753 T3414 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1190753 T3414 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1190753 T3414 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1369800262366
[junit4:junit4] 2> 1190755 T3414 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1369800262366\solr.xml
[junit4:junit4] 2> 1190755 T3414 oasc.CoreContainer.<init> New CoreContainer 12268698
[junit4:junit4] 2> 1190755 T3414 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1369800262366\'
[junit4:junit4] 2> 1190756 T3414 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1369800262366\'
[junit4:junit4] 2> 1190840 T3414 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1190840 T3414 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1190841 T3414 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1190841 T3414 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1190842 T3414 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1190842 T3414 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1190842 T3414 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1190842 T3414 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1190843 T3414 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1190843 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1190849 T3414 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1190849 T3414 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50370/solr
[junit4:junit4] 2> 1190849 T3414 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1190850 T3414 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1190863 T3486 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d93850 name:ZooKeeperConnection Watcher:127.0.0.1:50370 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1190863 T3414 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1190868 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1190880 T3414 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1190885 T3488 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@162785a name:ZooKeeperConnection Watcher:127.0.0.1:50370/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1190885 T3414 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1190898 T3414 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1191529 T3437 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1191530 T3437 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50398_e_fd_collection1",
[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:50398_e_fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50398/e_fd"}
[junit4:junit4] 2> 1191548 T3443 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> 1191548 T3456 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> 1191549 T3488 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> 1191548 T3436 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> 1191551 T3472 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> 1191655 T3414 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50407_e_fd
[junit4:junit4] 2> 1191659 T3414 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50407_e_fd
[junit4:junit4] 2> 1191666 T3436 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> 1191666 T3488 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> 1191666 T3472 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> 1191666 T3443 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> 1191670 T3456 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1191670 T3456 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> 1191677 T3436 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1191681 T3472 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1191682 T3443 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1191682 T3488 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1191691 T3489 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1369800262366\collection1
[junit4:junit4] 2> 1191691 T3489 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1191692 T3489 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1191692 T3489 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1191695 T3489 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1369800262366\collection1\'
[junit4:junit4] 2> 1191697 T3489 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1369800262366/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1191698 T3489 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1369800262366/collection1/lib/README' to classloader
[junit4:junit4] 2> 1191754 T3489 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1191804 T3489 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1191805 T3489 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1191810 T3489 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1192310 T3489 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1192313 T3489 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1192315 T3489 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1192321 T3489 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1192346 T3489 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1192347 T3489 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty3-1369800262366\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty3\
[junit4:junit4] 2> 1192347 T3489 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@177a9ff
[junit4:junit4] 2> 1192347 T3489 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1192348 T3489 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty3\
[junit4:junit4] 2> 1192348 T3489 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty3\index/
[junit4:junit4] 2> 1192348 T3489 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1369800251047\jetty3\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1192349 T3489 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty3\index
[junit4:junit4] 2> 1192352 T3489 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a7832 lockFactory=org.apache.lucene.store.NativeFSLockFactory@9d29b2),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1192352 T3489 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1192355 T3489 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1192355 T3489 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1192356 T3489 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1192356 T3489 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1192357 T3489 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1192357 T3489 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1192357 T3489 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1192358 T3489 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1192358 T3489 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1192366 T3489 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1192371 T3489 oass.SolrIndexSearcher.<init> Opening Searcher@19aea15 main
[junit4:junit4] 2> 1192371 T3489 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1369800251047\jetty3\tlog
[junit4:junit4] 2> 1192373 T3489 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1192374 T3489 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1192376 T3490 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@19aea15 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1192379 T3489 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1192379 T3489 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1192693 T3437 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1192694 T3437 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:50407_e_fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50407/e_fd"}
[junit4:junit4] 2> 1192695 T3437 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1192695 T3437 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1192712 T3443 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> 1192713 T3436 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> 1192714 T3456 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> 1192714 T3472 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> 1192714 T3488 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> 1193133 T3489 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1193133 T3489 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50407/e_fd collection:collection1 shard:shard1
[junit4:junit4] 2> 1193141 T3489 oasc.ZkController.register We are http://127.0.0.1:50407/e_fd/collection1/ and leader is http://127.0.0.1:50389/e_fd/collection1/
[junit4:junit4] 2> 1193142 T3489 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50407/e_fd
[junit4:junit4] 2> 1193142 T3489 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1193142 T3489 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2277 name=collection1 org.apache.solr.core.SolrCore@b5f6e4 url=http://127.0.0.1:50407/e_fd/collection1 node=127.0.0.1:50407_e_fd C2277_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:50407_e_fd, base_url=http://127.0.0.1:50407/e_fd}
[junit4:junit4] 2> 1193144 T3491 C2277 P50407 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1193144 T3489 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1193145 T3491 C2277 P50407 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1193147 T3491 C2277 P50407 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1193147 T3491 C2277 P50407 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1193150 T3414 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 1193150 T3414 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1193150 T3491 C2277 P50407 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1193151 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1193165 T3450 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:50407_e_fd_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1193488 T3414 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1193492 T3414 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50417
[junit4:junit4] 2> 1193493 T3414 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1193493 T3414 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1193493 T3414 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1369800265091
[junit4:junit4] 2> 1193494 T3414 oasc.CoreContainer$Initializer.initialize looking for solr config file: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1369800265091\solr.xml
[junit4:junit4] 2> 1193494 T3414 oasc.CoreContainer.<init> New CoreContainer 3820476
[junit4:junit4] 2> 1193494 T3414 oasc.CoreContainer.load Loading CoreContainer using Solr Home: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1369800265091\'
[junit4:junit4] 2> 1193495 T3414 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1369800265091\'
[junit4:junit4] 2> 1193591 T3414 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1193591 T3414 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1193592 T3414 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1193592 T3414 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1193592 T3414 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1193593 T3414 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1193593 T3414 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1193593 T3414 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1193593 T3414 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1193593 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1193599 T3414 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1193599 T3414 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:50370/solr
[junit4:junit4] 2> 1193600 T3414 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1193601 T3414 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1193612 T3503 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1bb7dd5 name:ZooKeeperConnection Watcher:127.0.0.1:50370 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1193613 T3414 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1193618 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1193618 T3416 oazs.NIOServerCnxn.doIO WARN caught end of stream exception EndOfStreamException: Unable to read additional data from client sessionid 0x13eee7516b2000b, 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> 1193626 T3414 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1193630 T3505 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3821de name:ZooKeeperConnection Watcher:127.0.0.1:50370/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1193631 T3414 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1193640 T3414 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1193856 T3437 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1193857 T3437 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50407_e_fd_collection1",
[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:50407_e_fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50407/e_fd"}
[junit4:junit4] 2> 1193872 T3505 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> 1193872 T3456 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> 1193874 T3488 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> 1193873 T3472 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> 1193872 T3436 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> 1193873 T3443 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> 1193917 T3450 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:50407_e_fd_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 1193917 T3450 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:50407_e_fd_collection1&state=recovering&nodeName=127.0.0.1:50407_e_fd&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=752
[junit4:junit4] 2> 1194395 T3414 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50417_e_fd
[junit4:junit4] 2> 1194401 T3414 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50417_e_fd
[junit4:junit4] 2> 1194408 T3505 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> 1194408 T3443 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> 1194409 T3436 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> 1194410 T3472 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> 1194409 T3488 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> 1194413 T3456 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1194413 T3456 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> 1194420 T3505 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1194421 T3443 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1194422 T3472 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1194422 T3436 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1194423 T3488 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1194429 T3506 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1369800265091\collection1
[junit4:junit4] 2> 1194429 T3506 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1194430 T3506 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1194430 T3506 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1194432 T3506 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: 'C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1369800265091\collection1\'
[junit4:junit4] 2> 1194433 T3506 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1369800265091/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1194434 T3506 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/C:/Users/JenkinsSlave/workspace/Lucene-Solr-trunk-Windows/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1369800265091/collection1/lib/README' to classloader
[junit4:junit4] 2> 1194483 T3506 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1194549 T3506 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1194551 T3506 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1194554 T3506 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1195052 T3506 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1195054 T3506 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1195057 T3506 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1195060 T3506 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1195086 T3506 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1195086 T3506 oasc.SolrCore.<init> [collection1] Opening new SolrCore at C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-jetty4-1369800265091\collection1\, dataDir=.\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty4\
[junit4:junit4] 2> 1195087 T3506 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@177a9ff
[junit4:junit4] 2> 1195087 T3506 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1195087 T3506 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty4\
[junit4:junit4] 2> 1195087 T3506 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=.\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty4\index/
[junit4:junit4] 2> 1195087 T3506 oasc.SolrCore.initIndex WARN [collection1] Solr index directory '.\org.apache.solr.cloud.ShardSplitTest-1369800251047\jetty4\index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1195088 T3506 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty4\index
[junit4:junit4] 2> 1195092 T3506 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d38125 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f35f0b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1195092 T3506 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1195095 T3506 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1195095 T3506 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1195096 T3506 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1195096 T3506 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1195097 T3506 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1195097 T3506 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1195097 T3506 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1195098 T3506 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1195098 T3506 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1195106 T3506 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1195121 T3506 oass.SolrIndexSearcher.<init> Opening Searcher@1c87d8f main
[junit4:junit4] 2> 1195122 T3506 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=.\org.apache.solr.cloud.ShardSplitTest-1369800251047\jetty4\tlog
[junit4:junit4] 2> 1195124 T3506 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1195124 T3506 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1195131 T3507 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1c87d8f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1195133 T3506 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1195133 T3506 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> ASYNC NEW_CORE C2278 name=collection1 org.apache.solr.core.SolrCore@b5f6e4 url=http://127.0.0.1:50407/e_fd/collection1 node=127.0.0.1:50407_e_fd C2278_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:50407_e_fd, base_url=http://127.0.0.1:50407/e_fd}
[junit4:junit4] 2> 1195420 T3491 C2278 P50407 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50389/e_fd/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1195420 T3491 C2278 P50407 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50407/e_fd START replicas=[http://127.0.0.1:50389/e_fd/collection1/] nUpdates=100
[junit4:junit4] 2> 1195422 T3491 C2278 P50407 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1195422 T3491 C2278 P50407 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1195423 T3491 C2278 P50407 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1195423 T3491 C2278 P50407 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1195424 T3491 C2278 P50407 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1195425 T3491 C2278 P50407 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50389/e_fd/collection1/. core=collection1
[junit4:junit4] 2> 1195426 T3491 C2278 P50407 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2279 name=collection1 org.apache.solr.core.SolrCore@3cb864 url=http://127.0.0.1:50389/e_fd/collection1 node=127.0.0.1:50389_e_fd C2279_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50389_e_fd, base_url=http://127.0.0.1:50389/e_fd, leader=true}
[junit4:junit4] 2> 1195432 T3451 C2279 P50389 oasc.SolrCore.execute [collection1] webapp=/e_fd path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 1195435 T3450 C2279 P50389 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1195439 T3450 C2279 P50389 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1cde652 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16baa67),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1195440 T3450 C2279 P50389 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1195440 T3450 C2279 P50389 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1cde652 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16baa67),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1cde652 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16baa67),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1195440 T3450 C2279 P50389 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1195440 T3450 C2279 P50389 oass.SolrIndexSearcher.<init> Opening Searcher@cd494f realtime
[junit4:junit4] 2> 1195441 T3450 C2279 P50389 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1195441 T3450 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd 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> 1195442 T3491 C2278 P50407 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1195442 T3491 C2278 P50407 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1195443 T3452 C2279 P50389 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1195444 T3452 C2279 P50389 oasc.SolrCore.execute [collection1] webapp=/e_fd path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 1195444 T3491 C2278 P50407 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1195444 T3491 C2278 P50407 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1195444 T3491 C2278 P50407 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1195446 T3448 C2279 P50389 oasc.SolrCore.execute [collection1] webapp=/e_fd path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 1195447 T3491 C2278 P50407 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1195448 T3491 C2278 P50407 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty3\index.20130528160427375
[junit4:junit4] 2> 1195448 T3491 C2278 P50407 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1c80637 lockFactory=org.apache.lucene.store.NativeFSLockFactory@314894) fullCopy=false
[junit4:junit4] 2> 1195450 T3449 C2279 P50389 oasc.SolrCore.execute [collection1] webapp=/e_fd path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1195451 T3491 C2278 P50407 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1195451 T3491 C2278 P50407 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1195452 T3491 C2278 P50407 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1195454 T3491 C2278 P50407 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a7832 lockFactory=org.apache.lucene.store.NativeFSLockFactory@9d29b2),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a7832 lockFactory=org.apache.lucene.store.NativeFSLockFactory@9d29b2),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1195455 T3491 C2278 P50407 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1195455 T3491 C2278 P50407 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1195455 T3491 C2278 P50407 oass.SolrIndexSearcher.<init> Opening Searcher@6e4ece main
[junit4:junit4] 2> 1195456 T3490 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6e4ece main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1195456 T3491 C2278 P50407 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty3\index.20130528160427375 [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty3\index.20130528160427375;done=true>>]
[junit4:junit4] 2> 1195456 T3491 C2278 P50407 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty3\index.20130528160427375
[junit4:junit4] 2> 1195456 T3491 C2278 P50407 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty3\index.20130528160427375
[junit4:junit4] 2> 1195456 T3491 C2278 P50407 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1195457 T3491 C2278 P50407 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1195457 T3491 C2278 P50407 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1195457 T3491 C2278 P50407 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1195460 T3491 C2278 P50407 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1196147 T3437 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1196150 T3437 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[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:50417_e_fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50417/e_fd"}
[junit4:junit4] 2> 1196150 T3437 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1196150 T3437 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1196164 T3437 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50407_e_fd_collection1",
[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:50407_e_fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50407/e_fd"}
[junit4:junit4] 2> 1196178 T3436 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> 1196179 T3443 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> 1196179 T3488 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> 1196179 T3505 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> 1196179 T3472 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> 1196179 T3456 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> 1196637 T3506 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1196637 T3506 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50417/e_fd collection:collection1 shard:shard2
[junit4:junit4] 2> 1196646 T3506 oasc.ZkController.register We are http://127.0.0.1:50417/e_fd/collection1/ and leader is http://127.0.0.1:50398/e_fd/collection1/
[junit4:junit4] 2> 1196646 T3506 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50417/e_fd
[junit4:junit4] 2> 1196647 T3506 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1196647 T3506 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2280 name=collection1 org.apache.solr.core.SolrCore@14a583f url=http://127.0.0.1:50417/e_fd/collection1 node=127.0.0.1:50417_e_fd C2280_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:50417_e_fd, base_url=http://127.0.0.1:50417/e_fd}
[junit4:junit4] 2> 1196648 T3510 C2280 P50417 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1196650 T3510 C2280 P50417 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1196650 T3510 C2280 P50417 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1196651 T3510 C2280 P50417 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1196650 T3506 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1196655 T3510 C2280 P50417 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1196656 T3414 oass.SolrDispatchFilter.init user.dir=C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0
[junit4:junit4] 2> 1196657 T3414 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1196659 T3414 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1196666 T3466 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:50417_e_fd_collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1196668 T3414 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1196670 T3414 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 1196671 T3414 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 1196673 T3414 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1197469 T3437 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1197472 T3437 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50417_e_fd_collection1",
[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:50417_e_fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50417/e_fd"}
[junit4:junit4] 2> 1197496 T3505 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> 1197496 T3488 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> 1197496 T3472 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> 1197496 T3436 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> 1197496 T3456 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> 1197497 T3443 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> 1197589 T3466 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:50417_e_fd_collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 1197589 T3466 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:50417_e_fd_collection1&state=recovering&nodeName=127.0.0.1:50417_e_fd&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=923
[junit4:junit4] 2> 1197600 T3414 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1198604 T3414 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C2280_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:50417_e_fd, base_url=http://127.0.0.1:50417/e_fd}
[junit4:junit4] 2> 1199591 T3510 C2280 P50417 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50398/e_fd/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1199591 T3510 C2280 P50417 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:50417/e_fd START replicas=[http://127.0.0.1:50398/e_fd/collection1/] nUpdates=100
[junit4:junit4] 2> 1199595 T3510 C2280 P50417 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1199595 T3510 C2280 P50417 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1199595 T3510 C2280 P50417 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1199596 T3510 C2280 P50417 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1199597 T3510 C2280 P50417 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1199597 T3510 C2280 P50417 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50398/e_fd/collection1/. core=collection1
[junit4:junit4] 2> 1199597 T3510 C2280 P50417 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2281 name=collection1 org.apache.solr.core.SolrCore@1a43b0b url=http://127.0.0.1:50398/e_fd/collection1 node=127.0.0.1:50398_e_fd C2281_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50398_e_fd, base_url=http://127.0.0.1:50398/e_fd, leader=true}
[junit4:junit4] 2> 1199605 T3466 C2281 P50398 oasc.SolrCore.execute [collection1] webapp=/e_fd path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 1199608 T3414 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1199611 T3468 C2281 P50398 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1199616 T3468 C2281 P50398 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@120db6d lockFactory=org.apache.lucene.store.NativeFSLockFactory@a1bae7),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1199617 T3468 C2281 P50398 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1199617 T3468 C2281 P50398 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@120db6d lockFactory=org.apache.lucene.store.NativeFSLockFactory@a1bae7),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@120db6d lockFactory=org.apache.lucene.store.NativeFSLockFactory@a1bae7),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1199618 T3468 C2281 P50398 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1199618 T3468 C2281 P50398 oass.SolrIndexSearcher.<init> Opening Searcher@ad1d14 realtime
[junit4:junit4] 2> 1199618 T3468 C2281 P50398 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1199619 T3468 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 1199619 T3510 C2280 P50417 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1199620 T3510 C2280 P50417 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1199622 T3464 C2281 P50398 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1199622 T3464 C2281 P50398 oasc.SolrCore.execute [collection1] webapp=/e_fd path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 1199623 T3510 C2280 P50417 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1199623 T3510 C2280 P50417 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1199623 T3510 C2280 P50417 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1199626 T3465 C2281 P50398 oasc.SolrCore.execute [collection1] webapp=/e_fd path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 1199627 T3510 C2280 P50417 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1199628 T3510 C2280 P50417 oasc.CachingDirectoryFactory.get return new directory for .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty4\index.20130528160431555
[junit4:junit4] 2> 1199628 T3510 C2280 P50417 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@108acca lockFactory=org.apache.lucene.store.NativeFSLockFactory@1c29d06) fullCopy=false
[junit4:junit4] 2> 1199631 T3467 C2281 P50398 oasc.SolrCore.execute [collection1] webapp=/e_fd path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 1199632 T3510 C2280 P50417 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1199633 T3510 C2280 P50417 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1199633 T3510 C2280 P50417 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1199636 T3510 C2280 P50417 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d38125 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f35f0b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d38125 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f35f0b),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1199638 T3510 C2280 P50417 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1199638 T3510 C2280 P50417 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1199638 T3510 C2280 P50417 oass.SolrIndexSearcher.<init> Opening Searcher@7c1937 main
[junit4:junit4] 2> 1199639 T3507 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7c1937 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1199640 T3510 C2280 P50417 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty4\index.20130528160431555 [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty4\index.20130528160431555;done=true>>]
[junit4:junit4] 2> 1199640 T3510 C2280 P50417 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty4\index.20130528160431555
[junit4:junit4] 2> 1199640 T3510 C2280 P50417 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty4\index.20130528160431555
[junit4:junit4] 2> 1199641 T3510 C2280 P50417 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1199641 T3510 C2280 P50417 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1199641 T3510 C2280 P50417 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1199641 T3510 C2280 P50417 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1199651 T3510 C2280 P50417 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1200522 T3437 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1200524 T3437 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50417_e_fd_collection1",
[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:50417_e_fd",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50417/e_fd"}
[junit4:junit4] 2> 1200545 T3505 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> 1200545 T3456 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> 1200547 T3488 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> 1200547 T3472 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> 1200545 T3436 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> 1200546 T3443 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> 1200611 T3414 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1200614 T3414 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C2282 name=collection1 org.apache.solr.core.SolrCore@18d20df url=http://127.0.0.1:50377/e_fd/collection1 node=127.0.0.1:50377_e_fd C2282_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:50377_e_fd, base_url=http://127.0.0.1:50377/e_fd, leader=true}
[junit4:junit4] 2> 1200637 T3429 C2282 P50377 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1200641 T3429 C2282 P50377 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d5acc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e9b364),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1200642 T3429 C2282 P50377 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1200642 T3429 C2282 P50377 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d5acc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e9b364),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d5acc3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e9b364),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1200642 T3429 C2282 P50377 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1200644 T3429 C2282 P50377 oass.SolrIndexSearcher.<init> Opening Searcher@5b4127 main
[junit4:junit4] 2> 1200644 T3429 C2282 P50377 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1200645 T3440 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5b4127 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1200646 T3429 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 1200655 T3463 C2281 P50398 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1200657 T3463 C2281 P50398 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@120db6d lockFactory=org.apache.lucene.store.NativeFSLockFactory@a1bae7),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@120db6d lockFactory=org.apache.lucene.store.NativeFSLockFactory@a1bae7),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1200657 T3463 C2281 P50398 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1200659 T3463 C2281 P50398 oass.SolrIndexSearcher.<init> Opening Searcher@1f3097 main
[junit4:junit4] 2> 1200659 T3463 C2281 P50398 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1200660 T3474 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f3097 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1200661 T3463 C2281 P50398 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:50389/e_fd/collection1/, StdNode: http://127.0.0.1:50407/e_fd/collection1/, StdNode: http://127.0.0.1:50417/e_fd/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 1200668 T3450 C2279 P50389 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C2278_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50407_e_fd, base_url=http://127.0.0.1:50407/e_fd}
[junit4:junit4] 2> 1200675 T3482 C2278 P50407 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C2280_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50417_e_fd, base_url=http://127.0.0.1:50417/e_fd}
[junit4:junit4] 2> 1200676 T3500 C2280 P50417 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1200677 T3482 C2278 P50407 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a7832 lockFactory=org.apache.lucene.store.NativeFSLockFactory@9d29b2),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5a7832 lockFactory=org.apache.lucene.store.NativeFSLockFactory@9d29b2),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1200678 T3482 C2278 P50407 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1200676 T3450 C2279 P50389 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1cde652 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16baa67),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1cde652 lockFactory=org.apache.lucene.store.NativeFSLockFactory@16baa67),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1200679 T3450 C2279 P50389 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1200679 T3482 C2278 P50407 oass.SolrIndexSearcher.<init> Opening Searcher@4aef2b main
[junit4:junit4] 2> 1200678 T3500 C2280 P50417 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d38125 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f35f0b),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d38125 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f35f0b),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1200680 T3482 C2278 P50407 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1200681 T3500 C2280 P50417 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1200681 T3500 C2280 P50417 oass.SolrIndexSearcher.<init> Opening Searcher@423646 main
[junit4:junit4] 2> 1200681 T3500 C2280 P50417 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1200680 T3450 C2279 P50389 oass.SolrIndexSearcher.<init> Opening Searcher@2244c3 main
[junit4:junit4] 2> 1200682 T3450 C2279 P50389 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1200681 T3490 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4aef2b main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1200683 T3458 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2244c3 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1200682 T3507 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@423646 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1200683 T3482 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 1200684 T3450 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 17
[junit4:junit4] 2> 1200685 T3500 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 1200685 T3463 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 30
[junit4:junit4] 2> 1200686 T3414 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1200689 T3448 C2279 P50389 oasc.SolrCore.execute [collection1] webapp=/e_fd path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1200691 T3483 C2278 P50407 oasc.SolrCore.execute [collection1] webapp=/e_fd path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1200693 T3464 C2281 P50398 oasc.SolrCore.execute [collection1] webapp=/e_fd path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1200695 T3496 C2280 P50417 oasc.SolrCore.execute [collection1] webapp=/e_fd path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 1202705 T3427 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436339692767281152)} 0 6
[junit4:junit4] 2> 1202723 T3481 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={update.distrib=FROMLEADER&_version_=-1436339692777766912&update.from=http://127.0.0.1:50389/e_fd/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436339692777766912)} 0 2
[junit4:junit4] 2> 1202727 T3501 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={update.distrib=FROMLEADER&_version_=-1436339692790349824&update.from=http://127.0.0.1:50398/e_fd/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436339692790349824)} 0 2
[junit4:junit4] 2> 1202728 T3468 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1436339692790349824)} 0 7
[junit4:junit4] 2> 1202729 T3450 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436339692777766912)} 0 20
[junit4:junit4] 2> 1202732 T3429 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[a!0 (1436339692801884160)]} 0 0
[junit4:junit4] 2> 1202738 T3496 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1436339692805029888)]} 0 0
[junit4:junit4] 2> 1202739 T3464 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[a!0 (1436339692805029888)]} 0 4
[junit4:junit4] 2> 1202742 T3430 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[b!1 (1436339692812369920)]} 0 0
[junit4:junit4] 2> 1202751 T3483 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1436339692819709952)]} 0 0
[junit4:junit4] 2> 1202753 T3448 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!1 (1436339692819709952)]} 0 4
[junit4:junit4] 2> 1202753 T3465 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[b!1]} 0 7
[junit4:junit4] 2> 1202756 T3431 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[c!2 (1436339692827049984)]} 0 0
[junit4:junit4] 2> 1202763 T3484 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1436339692831244288)]} 0 0
[junit4:junit4] 2> 1202764 T3449 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[c!2 (1436339692831244288)]} 0 4
[junit4:junit4] 2> 1202767 T3432 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[d!3 (1436339692838584320)]} 0 0
[junit4:junit4] 2> 1202775 T3497 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1436339692842778624)]} 0 1
[junit4:junit4] 2> 1202776 T3467 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[d!3 (1436339692842778624)]} 0 5
[junit4:junit4] 2> 1202780 T3428 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[e!4 (1436339692851167232)]} 0 1
[junit4:junit4] 2> 1202791 T3498 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1436339692859555840)]} 0 1
[junit4:junit4] 2> 1202792 T3466 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!4 (1436339692859555840)]} 0 5
[junit4:junit4] 2> 1202793 T3451 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[e!4]} 0 10
[junit4:junit4] 2> 1202796 T3427 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[f!5 (1436339692868993024)]} 0 0
[junit4:junit4] 2> 1202803 T3499 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1436339692872138752)]} 0 1
[junit4:junit4] 2> 1202804 T3463 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[f!5 (1436339692872138752)]} 0 5
[junit4:junit4] 2> 1202806 T3429 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[g!6 (1436339692879478784)]} 0 0
[junit4:junit4] 2> 1202817 T3479 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1436339692885770240)]} 0 1
[junit4:junit4] 2> 1202818 T3446 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!6 (1436339692885770240)]} 0 6
[junit4:junit4] 2> 1202819 T3468 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[g!6]} 0 10
[junit4:junit4] 2> 1202823 T3430 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[h!7 (1436339692896256000)]} 0 1
[junit4:junit4] 2> 1202833 T3480 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1436339692904644608)]} 0 1
[junit4:junit4] 2> 1202834 T3452 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!7 (1436339692904644608)]} 0 4
[junit4:junit4] 2> 1202835 T3464 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[h!7]} 0 9
[junit4:junit4] 2> 1202838 T3431 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[i!8 (1436339692913033216)]} 0 0
[junit4:junit4] 2> 1202845 T3482 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1436339692917227520)]} 0 1
[junit4:junit4] 2> 1202846 T3450 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[i!8 (1436339692917227520)]} 0 5
[junit4:junit4] 2> 1202849 T3432 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[j!9 (1436339692924567552)]} 0 0
[junit4:junit4] 2> 1202858 T3481 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1436339692930859008)]} 0 0
[junit4:junit4] 2> 1202860 T3448 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!9 (1436339692930859008)]} 0 5
[junit4:junit4] 2> 1202862 T3465 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[j!9]} 0 10
[junit4:junit4] 2> 1202866 T3428 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[k!10 (1436339692941344768)]} 0 1
[junit4:junit4] 2> 1202873 T3483 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1436339692945539072)]} 0 1
[junit4:junit4] 2> 1202874 T3449 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[k!10 (1436339692945539072)]} 0 5
[junit4:junit4] 2> 1202877 T3427 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[l!11 (1436339692953927680)]} 0 0
[junit4:junit4] 2> 1202888 T3500 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1436339692961267712)]} 0 1
[junit4:junit4] 2> 1202888 T3467 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!11 (1436339692961267712)]} 0 4
[junit4:junit4] 2> 1202889 T3451 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[l!11]} 0 8
[junit4:junit4] 2> 1202892 T3429 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[m!12 (1436339692969656320)]} 0 0
[junit4:junit4] 2> 1202898 T3501 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1436339692972802048)]} 0 0
[junit4:junit4] 2> 1202900 T3466 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[m!12 (1436339692972802048)]} 0 5
[junit4:junit4] 2> 1202903 T3430 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[n!13 (1436339692981190656)]} 0 0
[junit4:junit4] 2> 1202915 T3484 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1436339692988530688)]} 0 0
[junit4:junit4] 2> 1202916 T3446 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!13 (1436339692988530688)]} 0 6
[junit4:junit4] 2> 1202917 T3463 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[n!13]} 0 10
[junit4:junit4] 2> 1202921 T3431 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[o!14 (1436339693000065024)]} 0 0
[junit4:junit4] 2> 1202928 T3496 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1436339693004259328)]} 0 0
[junit4:junit4] 2> 1202930 T3468 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[o!14 (1436339693004259328)]} 0 5
[junit4:junit4] 2> 1202934 T3432 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[p!15 (1436339693013696512)]} 0 1
[junit4:junit4] 2> 1202942 T3479 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1436339693018939392)]} 0 1
[junit4:junit4] 2> 1202944 T3452 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[p!15 (1436339693018939392)]} 0 6
[junit4:junit4] 2> 1202947 T3428 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[q!16 (1436339693027328000)]} 0 0
[junit4:junit4] 2> 1202958 T3480 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1436339693035716608)]} 0 0
[junit4:junit4] 2> 1202960 T3450 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1436339693035716608)]} 0 6
[junit4:junit4] 2> 1202961 T3464 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[q!16]} 0 10
[junit4:junit4] 2> 1202964 T3427 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[r!17 (1436339693045153792)]} 0 0
[junit4:junit4] 2> 1202971 T3497 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1436339693050396672)]} 0 0
[junit4:junit4] 2> 1202972 T3465 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!17 (1436339693050396672)]} 0 3
[junit4:junit4] 2> 1202972 T3448 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[r!17]} 0 5
[junit4:junit4] 2> 1202975 T3429 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[s!18 (1436339693056688128)]} 0 0
[junit4:junit4] 2> 1202980 T3482 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1436339693059833856)]} 0 0
[junit4:junit4] 2> 1202981 T3449 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[s!18 (1436339693059833856)]} 0 3
[junit4:junit4] 2> 1202984 T3430 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[t!19 (1436339693066125312)]} 0 0
[junit4:junit4] 2> 1202989 T3481 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1436339693069271040)]} 0 0
[junit4:junit4] 2> 1202990 T3451 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[t!19 (1436339693069271040)]} 0 3
[junit4:junit4] 2> 1202992 T3431 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[u!20 (1436339693074513920)]} 0 0
[junit4:junit4] 2> 1203000 T3498 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1436339693080805376)]} 0 0
[junit4:junit4] 2> 1203001 T3467 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!20 (1436339693080805376)]} 0 3
[junit4:junit4] 2> 1203002 T3446 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[u!20]} 0 6
[junit4:junit4] 2> 1203004 T3432 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[v!21 (1436339693087096832)]} 0 0
[junit4:junit4] 2> 1203012 T3483 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1436339693092339712)]} 0 0
[junit4:junit4] 2> 1203013 T3452 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!21 (1436339693092339712)]} 0 4
[junit4:junit4] 2> 1203014 T3466 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[v!21]} 0 7
[junit4:junit4] 2> 1203017 T3428 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[w!22 (1436339693100728320)]} 0 0
[junit4:junit4] 2> 1203024 T3484 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1436339693104922624)]} 0 0
[junit4:junit4] 2> 1203025 T3450 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[w!22 (1436339693104922624)]} 0 4
[junit4:junit4] 2> 1203028 T3427 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[x!23 (1436339693112262656)]} 0 0
[junit4:junit4] 2> 1203035 T3499 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1436339693117505536)]} 0 0
[junit4:junit4] 2> 1203036 T3463 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!23 (1436339693117505536)]} 0 3
[junit4:junit4] 2> 1203037 T3448 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[x!23]} 0 6
[junit4:junit4] 2> 1203039 T3429 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[y!24 (1436339693123796992)]} 0 0
[junit4:junit4] 2> 1203046 T3500 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1436339693129039872)]} 0 0
[junit4:junit4] 2> 1203047 T3468 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[y!24 (1436339693129039872)]} 0 3
[junit4:junit4] 2> 1203048 T3449 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[y!24]} 0 6
[junit4:junit4] 2> 1203051 T3430 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[z!25 (1436339693136379904)]} 0 0
[junit4:junit4] 2> 1203055 T3479 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1436339693139525632)]} 0 0
[junit4:junit4] 2> 1203056 T3451 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[z!25 (1436339693139525632)]} 0 2
[junit4:junit4] 2> 1203059 T3431 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[a!26 (1436339693144768512)]} 0 0
[junit4:junit4] 2> 1203066 T3501 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1436339693150011392)]} 0 0
[junit4:junit4] 2> 1203067 T3464 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!26 (1436339693150011392)]} 0 3
[junit4:junit4] 2> 1203068 T3446 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[a!26]} 0 6
[junit4:junit4] 2> 1203070 T3432 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[b!27 (1436339693156302848)]} 0 0
[junit4:junit4] 2> 1203078 T3480 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1436339693159448576)]} 0 0
[junit4:junit4] 2> 1203079 T3452 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[b!27 (1436339693159448576)]} 0 6
[junit4:junit4] 2> 1203081 T3428 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[c!28 (1436339693167837184)]} 0 0
[junit4:junit4] 2> 1203088 T3482 C2278 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1436339693173080064)]} 0 0
[junit4:junit4] 2> 1203089 T3450 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[c!28 (1436339693173080064)]} 0 3
[junit4:junit4] 2> 1203091 T3465 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[c!28]} 0 7
[junit4:junit4] 2> 1203093 T3427 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[d!29 (1436339693180420096)]} 0 0
[junit4:junit4] 2> 1203099 T3496 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1436339693184614400)]} 0 0
[junit4:junit4] 2> 1203100 T3467 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!29 (1436339693184614400)]} 0 3
[junit4:junit4] 2> 1203100 T3448 C2279 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[d!29]} 0 4
[junit4:junit4] 2> 1203103 T3429 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[e!30 (1436339693190905856)]} 0 0
[junit4:junit4] 2> 1203108 T3497 C2280 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1436339693194051584)]} 0 0
[junit4:junit4] 2> 1203109 T3466 C2281 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[e!30 (1436339693194051584)]} 0 3
[junit4:junit4] 2> 1203112 T3431 C2282 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[f!31 (1436339693200343040)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C2283 name=collection1 org.apache.solr.core.SolrCore@14a583f url=http://127.0.0.1:50417/e_fd/collection1 node=127.0.0.1:50417_e_fd C2283_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50417_e_fd, base_url=http://127.0.0.1:50417/e_fd}
[junit4:junit4] 2> 1203130 T3498 C2283 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1436339693216071680)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C2284 name=collection1 org.apache.solr.core.SolrCore@1a43b0b url=http://127.0.0.1:50398/e_fd/collection1 node=127.0.0.1:50398_e_fd C2284_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50398_e_fd, base_url=http://127.0.0.1:50398/e_fd, leader=true}
[junit4:junit4] 2> 1203132 T3463 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[f!31 (1436339693216071680)]} 0 5
[junit4:junit4] 2> ASYNC NEW_CORE C2285 name=collection1 org.apache.solr.core.SolrCore@18d20df url=http://127.0.0.1:50377/e_fd/collection1 node=127.0.0.1:50377_e_fd C2285_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:50377_e_fd, base_url=http://127.0.0.1:50377/e_fd, leader=true}
[junit4:junit4] 2> 1203134 T3432 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[g!32 (1436339693223411712)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C2286 name=collection1 org.apache.solr.core.SolrCore@b5f6e4 url=http://127.0.0.1:50407/e_fd/collection1 node=127.0.0.1:50407_e_fd C2286_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50407_e_fd, base_url=http://127.0.0.1:50407/e_fd}
[junit4:junit4] 2> 1203138 T3481 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1436339693226557440)]} 0 0
[junit4:junit4] 2> ASYNC NEW_CORE C2287 name=collection1 org.apache.solr.core.SolrCore@3cb864 url=http://127.0.0.1:50389/e_fd/collection1 node=127.0.0.1:50389_e_fd C2287_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50389_e_fd, base_url=http://127.0.0.1:50389/e_fd, leader=true}
[junit4:junit4] 2> 1203139 T3449 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[g!32 (1436339693226557440)]} 0 2
[junit4:junit4] 2> 1203142 T3428 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[h!33 (1436339693231800320)]} 0 0
[junit4:junit4] 2> 1203149 T3484 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1436339693237043200)]} 0 0
[junit4:junit4] 2> 1203150 T3446 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!33 (1436339693237043200)]} 0 3
[junit4:junit4] 2> 1203151 T3464 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[h!33]} 0 6
[junit4:junit4] 2> 1203154 T3427 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[i!34 (1436339693244383232)]} 0 0
[junit4:junit4] 2> 1203162 T3479 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1436339693250674688)]} 0 0
[junit4:junit4] 2> 1203163 T3452 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!34 (1436339693250674688)]} 0 3
[junit4:junit4] 2> 1203164 T3465 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[i!34]} 0 6
[junit4:junit4] 2> 1203166 T3430 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[j!35 (1436339693256966144)]} 0 0
[junit4:junit4] 2> 1203171 T3480 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1436339693260111872)]} 0 0
[junit4:junit4] 2> 1203172 T3450 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[j!35 (1436339693260111872)]} 0 3
[junit4:junit4] 2> 1203175 T3429 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[k!36 (1436339693266403328)]} 0 0
[junit4:junit4] 2> 1203180 T3482 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1436339693269549056)]} 0 0
[junit4:junit4] 2> 1203181 T3448 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[k!36 (1436339693269549056)]} 0 3
[junit4:junit4] 2> 1203184 T3431 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[l!37 (1436339693275840512)]} 0 0
[junit4:junit4] 2> 1203189 T3500 C2283 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1436339693278986240)]} 0 0
[junit4:junit4] 2> 1203191 T3467 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[l!37 (1436339693278986240)]} 0 4
[junit4:junit4] 2> 1203194 T3432 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[m!38 (1436339693286326272)]} 0 0
[junit4:junit4] 2> 1203200 T3501 C2283 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1436339693289472000)]} 0 0
[junit4:junit4] 2> 1203201 T3466 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[m!38 (1436339693289472000)]} 0 4
[junit4:junit4] 2> 1203204 T3428 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[n!39 (1436339693296812032)]} 0 0
[junit4:junit4] 2> 1203213 T3483 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1436339693302054912)]} 0 1
[junit4:junit4] 2> 1203213 T3451 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!39 (1436339693302054912)]} 0 4
[junit4:junit4] 2> 1203214 T3468 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[n!39]} 0 7
[junit4:junit4] 2> 1203218 T3427 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[o!40 (1436339693311492096)]} 0 0
[junit4:junit4] 2> 1203225 T3496 C2283 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1436339693315686400)]} 0 0
[junit4:junit4] 2> 1203227 T3463 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[o!40 (1436339693315686400)]} 0 5
[junit4:junit4] 2> 1203229 T3430 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[p!41 (1436339693323026432)]} 0 0
[junit4:junit4] 2> 1203234 T3481 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1436339693326172160)]} 0 0
[junit4:junit4] 2> 1203235 T3449 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[p!41 (1436339693326172160)]} 0 3
[junit4:junit4] 2> 1203238 T3429 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[q!42 (1436339693332463616)]} 0 0
[junit4:junit4] 2> 1203248 T3484 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1436339693339803648)]} 0 1
[junit4:junit4] 2> 1203248 T3446 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!42 (1436339693339803648)]} 0 4
[junit4:junit4] 2> 1203250 T3464 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[q!42]} 0 9
[junit4:junit4] 2> 1203254 T3431 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[r!43 (1436339693349240832)]} 0 1
[junit4:junit4] 2> 1203263 T3497 C2283 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1436339693355532288)]} 0 0
[junit4:junit4] 2> 1203264 T3465 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!43 (1436339693355532288)]} 0 4
[junit4:junit4] 2> 1203266 T3452 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[r!43]} 0 9
[junit4:junit4] 2> 1203270 T3432 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[s!44 (1436339693366018048)]} 0 0
[junit4:junit4] 2> 1203276 T3479 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1436339693370212352)]} 0 0
[junit4:junit4] 2> 1203279 T3450 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[s!44 (1436339693370212352)]} 0 6
[junit4:junit4] 2> 1203283 T3428 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[t!45 (1436339693379649536)]} 0 0
[junit4:junit4] 2> 1203294 T3480 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1436339693388038144)]} 0 0
[junit4:junit4] 2> 1203296 T3448 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!45 (1436339693388038144)]} 0 6
[junit4:junit4] 2> 1203297 T3467 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[t!45]} 0 10
[junit4:junit4] 2> 1203301 T3427 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[u!46 (1436339693398523904)]} 0 0
[junit4:junit4] 2> 1203307 T3499 C2283 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1436339693402718208)]} 0 0
[junit4:junit4] 2> 1203310 T3466 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[u!46 (1436339693402718208)]} 0 5
[junit4:junit4] 2> 1203314 T3430 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[v!47 (1436339693412155392)]} 0 0
[junit4:junit4] 2> 1203325 T3482 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1436339693420544000)]} 0 1
[junit4:junit4] 2> 1203326 T3451 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!47 (1436339693420544000)]} 0 4
[junit4:junit4] 2> 1203327 T3468 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[v!47]} 0 9
[junit4:junit4] 2> 1203332 T3429 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[w!48 (1436339693431029760)]} 0 1
[junit4:junit4] 2> 1203342 T3483 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1436339693438369792)]} 0 1
[junit4:junit4] 2> 1203344 T3449 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!48 (1436339693438369792)]} 0 5
[junit4:junit4] 2> 1203345 T3463 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[w!48]} 0 10
[junit4:junit4] 2> 1203348 T3431 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[x!49 (1436339693447806976)]} 0 1
[junit4:junit4] 2> 1203358 T3498 C2283 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1436339693455147008)]} 0 0
[junit4:junit4] 2> 1203360 T3464 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!49 (1436339693455147008)]} 0 6
[junit4:junit4] 2> 1203361 T3446 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[x!49]} 0 10
[junit4:junit4] 2> 1203365 T3432 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[y!50 (1436339693464584192)]} 0 1
[junit4:junit4] 2> 1203371 T3500 C2283 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1436339693468778496)]} 0 0
[junit4:junit4] 2> 1203373 T3465 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[y!50 (1436339693468778496)]} 0 5
[junit4:junit4] 2> 1203377 T3428 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[z!51 (1436339693478215680)]} 0 1
[junit4:junit4] 2> 1203387 T3481 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1436339693484507136)]} 0 0
[junit4:junit4] 2> 1203388 T3452 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!51 (1436339693484507136)]} 0 5
[junit4:junit4] 2> 1203389 T3467 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[z!51]} 0 8
[junit4:junit4] 2> 1203393 T3427 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[a!52 (1436339693493944320)]} 0 1
[junit4:junit4] 2> 1203400 T3501 C2283 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1436339693499187200)]} 0 1
[junit4:junit4] 2> 1203402 T3466 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[a!52 (1436339693499187200)]} 0 6
[junit4:junit4] 2> 1203407 T3430 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[b!53 (1436339693508624384)]} 0 1
[junit4:junit4] 2> 1203414 T3484 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1436339693513867264)]} 0 1
[junit4:junit4] 2> 1203415 T3450 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[b!53 (1436339693513867264)]} 0 5
[junit4:junit4] 2> 1203420 T3429 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[c!54 (1436339693522255872)]} 0 0
[junit4:junit4] 2> 1203428 T3479 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1436339693528547328)]} 0 1
[junit4:junit4] 2> 1203429 T3448 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[c!54 (1436339693528547328)]} 0 5
[junit4:junit4] 2> 1203432 T3431 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[d!55 (1436339693535887360)]} 0 0
[junit4:junit4] 2> 1203444 T3496 C2283 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1436339693545324544)]} 0 1
[junit4:junit4] 2> 1203446 T3468 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!55 (1436339693545324544)]} 0 6
[junit4:junit4] 2> 1203447 T3451 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[d!55]} 0 10
[junit4:junit4] 2> 1203451 T3432 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[e!56 (1436339693555810304)]} 0 0
[junit4:junit4] 2> 1203460 T3497 C2283 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1436339693561053184)]} 0 1
[junit4:junit4] 2> 1203461 T3463 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[e!56 (1436339693561053184)]} 0 6
[junit4:junit4] 2> 1203465 T3428 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[f!57 (1436339693570490368)]} 0 0
[junit4:junit4] 2> 1203472 T3499 C2283 P50417 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50398/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1436339693575733248)]} 0 0
[junit4:junit4] 2> 1203472 T3464 C2284 P50398 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[f!57 (1436339693575733248)]} 0 3
[junit4:junit4] 2> 1203476 T3427 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[g!58 (1436339693582024704)]} 0 0
[junit4:junit4] 2> 1203482 T3480 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1436339693585170432)]} 0 0
[junit4:junit4] 2> 1203483 T3449 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[g!58 (1436339693585170432)]} 0 4
[junit4:junit4] 2> 1203485 T3430 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[h!59 (1436339693591461888)]} 0 0
[junit4:junit4] 2> 1203493 T3482 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1436339693595656192)]} 0 1
[junit4:junit4] 2> 1203494 T3446 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[h!59 (1436339693595656192)]} 0 5
[junit4:junit4] 2> 1203498 T3429 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[i!60 (1436339693605093376)]} 0 0
[junit4:junit4] 2> 1203507 T3483 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!60 (1436339693609287680)]} 0 1
[junit4:junit4] 2> 1203508 T3452 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[i!60 (1436339693609287680)]} 0 6
[junit4:junit4] 2> 1203513 T3431 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[j!61 (1436339693620822016)]} 0 1
[junit4:junit4] 2> 1203519 T3481 C2286 P50407 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={distrib.from=http://127.0.0.1:50389/e_fd/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!61 (1436339693622919168)]} 0 1
[junit4:junit4] 2> 1203520 T3450 C2287 P50389 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[j!61 (1436339693622919168)]} 0 5
[junit4:junit4] 2> 1203523 T3428 C2285 P50377 oasup.LogUpdateProcessor.finish [collection1] webapp=/e_fd path=/update params={wt=javabin&version=2} {add=[k!62 (1436339693631307776)]} 0
[...truncated too long message...]
ection1, collection=collection1, node_name=127.0.0.1:50417_e_fd, base_url=http://127.0.0.1:50417/e_fd, leader=true}
[junit4:junit4] 2> 1217647 T3414 C2312 P50417 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d38125 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f35f0b),segFN=segments_4,generation=4}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d38125 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f35f0b),segFN=segments_5,generation=5}
[junit4:junit4] 2> 1217648 T3414 C2312 P50417 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 5
[junit4:junit4] 2> 1217652 T3414 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 1217652 T3414 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1217652 T3414 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty4\index [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty4\index;done=false>>]
[junit4:junit4] 2> 1217653 T3414 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty4\index
[junit4:junit4] 2> 1217653 T3414 oasc.CachingDirectoryFactory.closeCacheValue looking to close .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty4\ [CachedDir<<refCount=0;path=.\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty4\;done=false>>]
[junit4:junit4] 2> 1217654 T3414 oasc.CachingDirectoryFactory.close Closing directory: .\org.apache.solr.cloud.ShardSplitTest-1369800251047/jetty4\
[junit4:junit4] 2> 1217656 T3540 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89771229253337100-127.0.0.1:50417_e_fd-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 1217659 T3505 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> 1217673 T3414 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/e_fd,null}
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-1369800251047\zookeeper\server1\data\version-2\log.1 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-1369800251047\zookeeper\server1\data\version-2 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-1369800251047\zookeeper\server1\data FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-1369800251047\zookeeper\server1 FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-1369800251047\zookeeper FAILED !!!!!
[junit4:junit4] 2> !!!! WARNING: best effort to remove C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build\solr-core\test\J0\.\org.apache.solr.cloud.ShardSplitTest-1369800251047 FAILED !!!!!
[junit4:junit4] 2> 1217804 T3414 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1217808 T3414 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:50370 50370
[junit4:junit4] 2> 1219091 T3505 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1220283 T3505 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1220286 T3414 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 50377
[junit4:junit4] 2> 1220306 T3414 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1220306 T3414 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:50370 50370
[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=5C186D28EE33AF39 -Dtests.slow=true -Dtests.locale=en_NZ -Dtests.timezone=Etc/GMT+12 -Dtests.file.encoding=ISO-8859-1
[junit4:junit4] ERROR 41.2s | ShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:50389/e_fd returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([5C186D28EE33AF39:DDFEE330996CCF05]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.doTest(ShardSplitTest.java:133)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 1220327 T3414 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=PostingsFormat(name=SimpleText), _version_=PostingsFormat(name=Direct)}, docValues:{}, sim=DefaultSimilarity, locale=en_NZ, timezone=Etc/GMT+12
[junit4:junit4] 2> NOTE: Windows 7 6.1 x86/Oracle Corporation 1.7.0_21 (32-bit)/cpus=2,threads=4,free=55214144,total=198500352
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SolrCmdDistributorTest, StatelessScriptUpdateProcessorFactoryTest, SuggesterFSTTest, TestSolrQueryParser, TestStressRecovery, TestFastWriter, TestPostingsSolrHighlighter, TestExtendedDismaxParser, TestPHPSerializedResponseWriter, FileBasedSpellCheckerTest, MultiTermTest, TestCSVLoader, SortByFunctionTest, TestGroupingSearch, TestWordDelimiterFilterFactory, TestPhraseSuggestions, TestCharFilters, SynonymTokenizerTest, IndexBasedSpellCheckerTest, TestFaceting, URLClassifyProcessorTest, TimeZoneUtilsTest, TestSchemaSimilarityResource, HighlighterConfigTest, SliceStateUpdateTest, TestSolr4Spatial, TestPluginEnable, TestSchemaVersionResource, TestCoreDiscovery, ResponseLogComponentTest, TestSerializedLuceneMatchVersion, TestLMDirichletSimilarityFactory, SampleTest, SearchHandlerTest, MinimalSchemaTest, TestUniqueKeyFieldResource, CircularListTest, HardAutoCommitTest, ChaosMonkeySafeLeaderTest, TestTrie, QueryElevationComponentTest, CSVRequestHandlerTest, OverseerCollectionProcessorTest, TestCloudManagedSchemaAddField, TestDefaultSearchFieldResource, FieldMutatingUpdateProcessorTest, PingRequestHandlerTest, TestSystemIdResolver, DirectSolrSpellCheckerTest, TestDocSet, TestXIncludeConfig, ZkSolrClientTest, WordBreakSolrSpellCheckerTest, ShardRoutingCustomTest, TestPseudoReturnFields, ZkNodePropsTest, BadComponentTest, TestSchemaNameResource, SolrIndexConfigTest, BadIndexSchemaTest, TestReplicationHandler, LoggingHandlerTest, ZkCLITest, TestManagedSchemaFieldResource, QueryResultKeyTest, CopyFieldTest, TestZkChroot, SolrTestCaseJ4Test, TestIndexSearcher, NumericFieldsTest, UUIDFieldTest, IndexSchemaTest, BasicDistributedZkTest, TestLRUCache, UpdateParamsTest, SolrInfoMBeanTest, TestDFRSimilarityFactory, TestSolrXml, TestConfig, TestFastOutputStream, TestFoldingMultitermQuery, TestRandomFaceting, TestLMJelinekMercerSimilarityFactory, DistributedTermsComponentTest, SimpleFacetsTest, OutputWriterTest, TestBM25SimilarityFactory, TestSort, TestSearchPerf, LegacyHTMLStripCharFilterTest, TestPropInjectDefaults, LeaderElectionIntegrationTest, RequestHandlersTest, TestBadConfig, TestIBSimilarityFactory, AutoCommitTest, AliasIntegrationTest, AnalysisAfterCoreReloadTest, TestHashPartitioner, SolrRequestParserTest, PrimUtilsTest, DisMaxRequestHandlerTest, TestLuceneMatchVersion, TestStressReorder, BasicDistributedZk2Test, DocValuesMultiTest, TestReload, ResourceLoaderTest, TestFiltering, DocValuesTest, ShardSplitTest]
[junit4:junit4] Completed in 41.24s, 1 test, 1 error <<< FAILURES!
[...truncated 579 lines...]
BUILD FAILED
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:380: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:360: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\build.xml:39: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\build.xml:181: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\solr\common-build.xml:437: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:1240: The following error occurred while executing this line:
C:\Users\JenkinsSlave\workspace\Lucene-Solr-trunk-Windows\lucene\common-build.xml:884: There were test failures: 295 suites, 1232 tests, 1 error, 18 ignored (12 assumptions)
Total time: 67 minutes 17 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_21 -client -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure