You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Apache Jenkins Server <je...@builds.apache.org> on 2013/05/20 18:45:04 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java7 - Build # 1267 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java7/1267/
2 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:52246/mp/aq 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:52246/mp/aq returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([64E59B5A18A6FC2F:E50315426FF99C13]: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.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
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)
FAILED: org.apache.solr.cloud.ShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:19750/_pe/ff 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:19750/_pe/ff returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([64E59B5A18A6FC2F:E50315426FF99C13]: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 9557 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ShardSplitTest
[junit4:junit4] 2> 865385 T1842 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /_pe/ff
[junit4:junit4] 2> 865389 T1842 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./solrtest-ShardSplitTest-1369067474044
[junit4:junit4] 2> 865390 T1842 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 865391 T1843 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 865492 T1842 oasc.ZkTestServer.run start zk server on port:29569
[junit4:junit4] 2> 865493 T1842 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 865497 T1849 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6efb2c34 name:ZooKeeperConnection Watcher:127.0.0.1:29569 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 865497 T1842 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 865498 T1842 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 865510 T1842 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 865512 T1851 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@77d5e0bd name:ZooKeeperConnection Watcher:127.0.0.1:29569/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 865512 T1842 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 865512 T1842 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 865523 T1842 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 865525 T1842 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 865528 T1842 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 865530 T1842 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 865531 T1842 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 865536 T1842 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 865537 T1842 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 865640 T1842 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 865641 T1842 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 865650 T1842 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 865651 T1842 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 865654 T1842 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 865655 T1842 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 865658 T1842 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 865659 T1842 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 865662 T1842 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 865662 T1842 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 865665 T1842 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 865666 T1842 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 865676 T1842 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 865677 T1842 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 865858 T1842 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 865862 T1842 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:16142
[junit4:junit4] 2> 865862 T1842 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 865863 T1842 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 865863 T1842 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369067474343
[junit4:junit4] 2> 865863 T1842 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369067474343/solr.xml
[junit4:junit4] 2> 865864 T1842 oasc.CoreContainer.<init> New CoreContainer 1219238415
[junit4:junit4] 2> 865864 T1842 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369067474343/'
[junit4:junit4] 2> 865865 T1842 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369067474343/'
[junit4:junit4] 2> 865948 T1842 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 865949 T1842 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 865950 T1842 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 865950 T1842 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 865950 T1842 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 865951 T1842 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 865951 T1842 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 865952 T1842 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 865952 T1842 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 865952 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 865964 T1842 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 865964 T1842 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:29569/solr
[junit4:junit4] 2> 865965 T1842 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 865965 T1842 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 865969 T1862 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@b8896b8 name:ZooKeeperConnection Watcher:127.0.0.1:29569 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 865970 T1842 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 865983 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 865995 T1842 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 865997 T1864 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4f8d74fd name:ZooKeeperConnection Watcher:127.0.0.1:29569/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 865997 T1842 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 866000 T1842 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 866011 T1842 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 866014 T1842 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 866017 T1842 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:16142__pe%2Fff
[junit4:junit4] 2> 866024 T1842 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:16142__pe%2Fff
[junit4:junit4] 2> 866027 T1842 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 866045 T1842 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 866048 T1842 oasc.Overseer.start Overseer (id=89723205979406339-127.0.0.1:16142__pe%2Fff-n_0000000000) starting
[junit4:junit4] 2> 866060 T1842 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 866072 T1866 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 866072 T1842 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 866075 T1842 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 866077 T1842 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 866080 T1865 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 866084 T1867 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369067474343/collection1
[junit4:junit4] 2> 866084 T1867 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 866085 T1867 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 866085 T1867 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 866087 T1867 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369067474343/collection1/'
[junit4:junit4] 2> 866088 T1867 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1369067474343/collection1/lib/README' to classloader
[junit4:junit4] 2> 866089 T1867 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-controljetty-1369067474343/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 866141 T1867 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 866201 T1867 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 866302 T1867 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 866308 T1867 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 866869 T1867 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 866873 T1867 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 866875 T1867 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 866880 T1867 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 866904 T1867 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 866905 T1867 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-controljetty-1369067474343/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1369067474043/control/data/
[junit4:junit4] 2> 866905 T1867 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1734f867
[junit4:junit4] 2> 866906 T1867 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 866907 T1867 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369067474043/control/data
[junit4:junit4] 2> 866907 T1867 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1369067474043/control/data/index/
[junit4:junit4] 2> 866907 T1867 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1369067474043/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 866908 T1867 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369067474043/control/data/index
[junit4:junit4] 2> 866912 T1867 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1325e8eb lockFactory=org.apache.lucene.store.NativeFSLockFactory@62153bf1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 866913 T1867 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 866915 T1867 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 866916 T1867 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 866917 T1867 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 866917 T1867 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 866918 T1867 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 866918 T1867 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 866918 T1867 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 866919 T1867 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 866919 T1867 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 866936 T1867 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 866943 T1867 oass.SolrIndexSearcher.<init> Opening Searcher@237d17b1 main
[junit4:junit4] 2> 866943 T1867 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1369067474043/control/data/tlog
[junit4:junit4] 2> 866945 T1867 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 866945 T1867 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 866948 T1868 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@237d17b1 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 866949 T1867 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 866949 T1867 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 867584 T1865 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 867585 T1865 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:16142__pe%2Fff",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:16142/_pe/ff"}
[junit4:junit4] 2> 867585 T1865 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 867585 T1865 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 867600 T1864 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> 867952 T1867 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 867952 T1867 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:16142/_pe/ff collection:control_collection shard:shard1
[junit4:junit4] 2> 867953 T1867 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 867977 T1867 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 867979 T1867 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 867980 T1867 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 867980 T1867 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:16142/_pe/ff/collection1/
[junit4:junit4] 2> 867980 T1867 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 867981 T1867 oasc.SyncStrategy.syncToMe http://127.0.0.1:16142/_pe/ff/collection1/ has no replicas
[junit4:junit4] 2> 867981 T1867 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:16142/_pe/ff/collection1/
[junit4:junit4] 2> 867981 T1867 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 869110 T1865 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 869129 T1864 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> 869160 T1867 oasc.ZkController.register We are http://127.0.0.1:16142/_pe/ff/collection1/ and leader is http://127.0.0.1:16142/_pe/ff/collection1/
[junit4:junit4] 2> 869160 T1867 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:16142/_pe/ff
[junit4:junit4] 2> 869160 T1867 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 869160 T1867 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 869161 T1867 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 869163 T1867 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 869164 T1842 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 869165 T1842 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 869165 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 869181 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 869183 T1842 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 869185 T1871 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@36ddcc72 name:ZooKeeperConnection Watcher:127.0.0.1:29569/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 869185 T1842 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 869187 T1842 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 869190 T1842 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 869448 T1842 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 869451 T1842 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:19750
[junit4:junit4] 2> 869452 T1842 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 869453 T1842 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 869453 T1842 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369067477844
[junit4:junit4] 2> 869454 T1842 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369067477844/solr.xml
[junit4:junit4] 2> 869454 T1842 oasc.CoreContainer.<init> New CoreContainer 611010887
[junit4:junit4] 2> 869455 T1842 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369067477844/'
[junit4:junit4] 2> 869456 T1842 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369067477844/'
[junit4:junit4] 2> 869582 T1842 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 869583 T1842 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 869584 T1842 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 869584 T1842 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 869585 T1842 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 869585 T1842 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 869586 T1842 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 869587 T1842 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 869587 T1842 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 869588 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 869603 T1842 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 869604 T1842 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:29569/solr
[junit4:junit4] 2> 869605 T1842 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 869606 T1842 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 869726 T1882 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@786cb52e name:ZooKeeperConnection Watcher:127.0.0.1:29569 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 869727 T1842 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 869730 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 869741 T1842 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 869749 T1884 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@20b31ab4 name:ZooKeeperConnection Watcher:127.0.0.1:29569/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 869750 T1842 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 869755 T1842 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 870641 T1865 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 870642 T1865 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:16142__pe%2Fff",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:16142/_pe/ff"}
[junit4:junit4] 2> 870680 T1864 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> 870680 T1884 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> 870680 T1871 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> 870759 T1842 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:19750__pe%2Fff
[junit4:junit4] 2> 870762 T1842 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:19750__pe%2Fff
[junit4:junit4] 2> 870764 T1864 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> 870764 T1884 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> 870765 T1871 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 870765 T1871 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> 870766 T1864 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 870766 T1884 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 870777 T1885 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369067477844/collection1
[junit4:junit4] 2> 870778 T1885 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 870778 T1885 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 870779 T1885 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 870780 T1885 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369067477844/collection1/'
[junit4:junit4] 2> 870782 T1885 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1369067477844/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 870782 T1885 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty1-1369067477844/collection1/lib/README' to classloader
[junit4:junit4] 2> 870833 T1885 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 870892 T1885 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 870993 T1885 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 870999 T1885 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 871539 T1885 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 871543 T1885 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 871544 T1885 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 871548 T1885 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 871570 T1885 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 871570 T1885 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty1-1369067477844/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty1/
[junit4:junit4] 2> 871571 T1885 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1734f867
[junit4:junit4] 2> 871571 T1885 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 871572 T1885 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty1
[junit4:junit4] 2> 871572 T1885 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty1/index/
[junit4:junit4] 2> 871572 T1885 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 871573 T1885 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty1/index
[junit4:junit4] 2> 871576 T1885 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a547b7a lockFactory=org.apache.lucene.store.NativeFSLockFactory@1096d1c1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 871576 T1885 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 871578 T1885 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 871578 T1885 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 871579 T1885 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 871579 T1885 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 871580 T1885 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 871580 T1885 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 871580 T1885 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 871581 T1885 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 871581 T1885 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 871591 T1885 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 871596 T1885 oass.SolrIndexSearcher.<init> Opening Searcher@494b1163 main
[junit4:junit4] 2> 871597 T1885 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty1/tlog
[junit4:junit4] 2> 871597 T1885 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 871598 T1885 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 871601 T1886 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@494b1163 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 871602 T1885 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 871602 T1885 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 872185 T1865 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 872186 T1865 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:19750__pe%2Fff",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19750/_pe/ff"}
[junit4:junit4] 2> 872186 T1865 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 872186 T1865 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 872190 T1864 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> 872190 T1871 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> 872190 T1884 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> 872605 T1885 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 872605 T1885 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:19750/_pe/ff collection:collection1 shard:shard1
[junit4:junit4] 2> 872606 T1885 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 872671 T1885 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 872674 T1885 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 872674 T1885 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 872675 T1885 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:19750/_pe/ff/collection1/
[junit4:junit4] 2> 872675 T1885 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 872675 T1885 oasc.SyncStrategy.syncToMe http://127.0.0.1:19750/_pe/ff/collection1/ has no replicas
[junit4:junit4] 2> 872675 T1885 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:19750/_pe/ff/collection1/
[junit4:junit4] 2> 872676 T1885 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 873710 T1865 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 873742 T1864 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> 873742 T1884 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> 873742 T1871 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> 873753 T1885 oasc.ZkController.register We are http://127.0.0.1:19750/_pe/ff/collection1/ and leader is http://127.0.0.1:19750/_pe/ff/collection1/
[junit4:junit4] 2> 873753 T1885 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:19750/_pe/ff
[junit4:junit4] 2> 873753 T1885 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 873754 T1885 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 873754 T1885 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 873756 T1885 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 873757 T1842 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 873758 T1842 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 873758 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 874069 T1842 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 874073 T1842 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:46856
[junit4:junit4] 2> 874073 T1842 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 874074 T1842 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 874075 T1842 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369067482431
[junit4:junit4] 2> 874075 T1842 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369067482431/solr.xml
[junit4:junit4] 2> 874076 T1842 oasc.CoreContainer.<init> New CoreContainer 861646160
[junit4:junit4] 2> 874077 T1842 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369067482431/'
[junit4:junit4] 2> 874077 T1842 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369067482431/'
[junit4:junit4] 2> 874220 T1842 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 874221 T1842 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 874222 T1842 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 874223 T1842 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 874223 T1842 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 874224 T1842 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 874224 T1842 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 874225 T1842 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 874225 T1842 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 874226 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 874262 T1842 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 874263 T1842 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:29569/solr
[junit4:junit4] 2> 874264 T1842 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 874265 T1842 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 874268 T1898 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6e02ed63 name:ZooKeeperConnection Watcher:127.0.0.1:29569 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 874269 T1842 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 874285 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 874298 T1842 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 874300 T1900 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5f5d03e9 name:ZooKeeperConnection Watcher:127.0.0.1:29569/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 874301 T1842 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 874310 T1842 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 875249 T1865 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 875250 T1865 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:19750__pe%2Fff",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19750/_pe/ff"}
[junit4:junit4] 2> 875263 T1871 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> 875263 T1884 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> 875263 T1900 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> 875263 T1864 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> 875314 T1842 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46856__pe%2Fff
[junit4:junit4] 2> 875316 T1842 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46856__pe%2Fff
[junit4:junit4] 2> 875353 T1900 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> 875353 T1864 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> 875353 T1884 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> 875354 T1871 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 875355 T1871 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> 875355 T1900 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 875356 T1864 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 875357 T1884 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 875362 T1901 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369067482431/collection1
[junit4:junit4] 2> 875362 T1901 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 875363 T1901 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 875363 T1901 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 875365 T1901 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369067482431/collection1/'
[junit4:junit4] 2> 875366 T1901 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1369067482431/collection1/lib/README' to classloader
[junit4:junit4] 2> 875367 T1901 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty2-1369067482431/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 875419 T1901 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 875477 T1901 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 875579 T1901 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 875585 T1901 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 876123 T1901 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 876127 T1901 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 876129 T1901 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 876134 T1901 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 876157 T1901 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 876158 T1901 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty2-1369067482431/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty2/
[junit4:junit4] 2> 876158 T1901 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1734f867
[junit4:junit4] 2> 876159 T1901 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 876159 T1901 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty2
[junit4:junit4] 2> 876160 T1901 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty2/index/
[junit4:junit4] 2> 876160 T1901 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 876161 T1901 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty2/index
[junit4:junit4] 2> 876165 T1901 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@df6fdcf lockFactory=org.apache.lucene.store.NativeFSLockFactory@626a80cc),segFN=segments_1,generation=1}
[junit4:junit4] 2> 876165 T1901 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 876168 T1901 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 876168 T1901 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 876169 T1901 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 876170 T1901 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 876170 T1901 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 876170 T1901 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 876171 T1901 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 876171 T1901 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 876172 T1901 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 876187 T1901 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 876194 T1901 oass.SolrIndexSearcher.<init> Opening Searcher@452c44ca main
[junit4:junit4] 2> 876194 T1901 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty2/tlog
[junit4:junit4] 2> 876195 T1901 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 876196 T1901 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 876200 T1902 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@452c44ca main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 876202 T1901 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 876202 T1901 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 876771 T1865 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 876772 T1865 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46856__pe%2Fff",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46856/_pe/ff"}
[junit4:junit4] 2> 876773 T1865 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 876773 T1865 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 876777 T1900 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> 876777 T1884 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> 876777 T1864 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> 876777 T1871 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> 877205 T1901 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 877205 T1901 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46856/_pe/ff collection:collection1 shard:shard2
[junit4:junit4] 2> 877206 T1901 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 877213 T1901 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 877216 T1901 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 877216 T1901 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 877217 T1901 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:46856/_pe/ff/collection1/
[junit4:junit4] 2> 877217 T1901 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 877217 T1901 oasc.SyncStrategy.syncToMe http://127.0.0.1:46856/_pe/ff/collection1/ has no replicas
[junit4:junit4] 2> 877217 T1901 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:46856/_pe/ff/collection1/
[junit4:junit4] 2> 877218 T1901 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 878282 T1865 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 878290 T1864 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> 878290 T1884 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> 878290 T1871 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> 878290 T1900 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> 878297 T1901 oasc.ZkController.register We are http://127.0.0.1:46856/_pe/ff/collection1/ and leader is http://127.0.0.1:46856/_pe/ff/collection1/
[junit4:junit4] 2> 878297 T1901 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46856/_pe/ff
[junit4:junit4] 2> 878297 T1901 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 878297 T1901 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 878297 T1901 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 878299 T1901 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 878300 T1842 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 878301 T1842 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 878301 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 878592 T1842 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 878596 T1842 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:31621
[junit4:junit4] 2> 878597 T1842 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 878598 T1842 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 878599 T1842 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369067486973
[junit4:junit4] 2> 878599 T1842 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369067486973/solr.xml
[junit4:junit4] 2> 878600 T1842 oasc.CoreContainer.<init> New CoreContainer 208052894
[junit4:junit4] 2> 878601 T1842 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369067486973/'
[junit4:junit4] 2> 878602 T1842 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369067486973/'
[junit4:junit4] 2> 878731 T1842 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 878732 T1842 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 878733 T1842 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 878733 T1842 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 878734 T1842 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 878734 T1842 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 878735 T1842 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 878735 T1842 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 878736 T1842 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 878737 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 878754 T1842 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 878754 T1842 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:29569/solr
[junit4:junit4] 2> 878755 T1842 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 878757 T1842 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 878762 T1914 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@34a6c2fb name:ZooKeeperConnection Watcher:127.0.0.1:29569 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 878763 T1842 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 878767 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 878779 T1842 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 878782 T1916 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5e06b47d name:ZooKeeperConnection Watcher:127.0.0.1:29569/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 878782 T1842 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 878794 T1842 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 879796 T1865 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 879796 T1865 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46856__pe%2Fff",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46856/_pe/ff"}
[junit4:junit4] 2> 879798 T1842 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:31621__pe%2Fff
[junit4:junit4] 2> 879815 T1842 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:31621__pe%2Fff
[junit4:junit4] 2> 879816 T1871 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> 879816 T1884 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> 879816 T1900 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> 879816 T1916 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> 879816 T1864 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> 879819 T1884 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> 879819 T1871 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 879819 T1900 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> 879819 T1871 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> 879820 T1916 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 879820 T1884 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 879820 T1864 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> 879821 T1900 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 879822 T1864 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 879827 T1917 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369067486973/collection1
[junit4:junit4] 2> 879827 T1917 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 879828 T1917 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 879828 T1917 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 879830 T1917 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369067486973/collection1/'
[junit4:junit4] 2> 879831 T1917 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1369067486973/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 879832 T1917 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty3-1369067486973/collection1/lib/README' to classloader
[junit4:junit4] 2> 879883 T1917 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 879942 T1917 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 880044 T1917 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 880050 T1917 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 880677 T1917 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 880682 T1917 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 880684 T1917 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 880690 T1917 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 880722 T1917 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 880723 T1917 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty3-1369067486973/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty3/
[junit4:junit4] 2> 880724 T1917 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1734f867
[junit4:junit4] 2> 880725 T1917 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 880727 T1917 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty3
[junit4:junit4] 2> 880727 T1917 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty3/index/
[junit4:junit4] 2> 880727 T1917 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 880728 T1917 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty3/index
[junit4:junit4] 2> 880732 T1917 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@34c7a165 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44bc2057),segFN=segments_1,generation=1}
[junit4:junit4] 2> 880732 T1917 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 880735 T1917 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 880736 T1917 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 880737 T1917 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 880737 T1917 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 880738 T1917 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 880738 T1917 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 880739 T1917 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 880739 T1917 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 880740 T1917 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 880756 T1917 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 880763 T1917 oass.SolrIndexSearcher.<init> Opening Searcher@7013e7ed main
[junit4:junit4] 2> 880764 T1917 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty3/tlog
[junit4:junit4] 2> 880765 T1917 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 880766 T1917 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 880770 T1918 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7013e7ed main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 880772 T1917 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 880773 T1917 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 881322 T1865 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 881323 T1865 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:31621__pe%2Fff",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:31621/_pe/ff"}
[junit4:junit4] 2> 881323 T1865 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 881323 T1865 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 881327 T1871 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> 881328 T1916 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> 881328 T1900 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> 881328 T1884 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> 881327 T1864 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> 881775 T1917 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 881775 T1917 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:31621/_pe/ff collection:collection1 shard:shard1
[junit4:junit4] 2> 881778 T1917 oasc.ZkController.register We are http://127.0.0.1:31621/_pe/ff/collection1/ and leader is http://127.0.0.1:19750/_pe/ff/collection1/
[junit4:junit4] 2> 881779 T1917 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:31621/_pe/ff
[junit4:junit4] 2> 881779 T1917 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 881779 T1917 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C131 name=collection1 org.apache.solr.core.SolrCore@137bce05 url=http://127.0.0.1:31621/_pe/ff/collection1 node=127.0.0.1:31621__pe%2Fff C131_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:31621__pe%2Fff, base_url=http://127.0.0.1:31621/_pe/ff}
[junit4:junit4] 2> 881780 T1919 C131 P31621 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 881781 T1917 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 881781 T1919 C131 P31621 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 881782 T1919 C131 P31621 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 881782 T1919 C131 P31621 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 881782 T1842 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 881783 T1842 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 881783 T1919 C131 P31621 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 881784 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 881805 T1874 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 882068 T1842 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 882072 T1842 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:31631
[junit4:junit4] 2> 882072 T1842 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 882073 T1842 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 882073 T1842 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369067490457
[junit4:junit4] 2> 882074 T1842 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369067490457/solr.xml
[junit4:junit4] 2> 882075 T1842 oasc.CoreContainer.<init> New CoreContainer 900960654
[junit4:junit4] 2> 882075 T1842 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369067490457/'
[junit4:junit4] 2> 882076 T1842 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369067490457/'
[junit4:junit4] 2> 882203 T1842 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 882204 T1842 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 882204 T1842 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 882205 T1842 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 882205 T1842 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 882206 T1842 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 882206 T1842 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 882207 T1842 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 882207 T1842 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 882208 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 882225 T1842 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 882226 T1842 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:29569/solr
[junit4:junit4] 2> 882226 T1842 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 882228 T1842 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 882231 T1931 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@65d12f16 name:ZooKeeperConnection Watcher:127.0.0.1:29569 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 882231 T1842 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 882250 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 882267 T1842 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 882309 T1933 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5aae84bd name:ZooKeeperConnection Watcher:127.0.0.1:29569/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 882310 T1842 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 882328 T1842 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 882833 T1865 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 882834 T1865 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:31621__pe%2Fff",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:31621/_pe/ff"}
[junit4:junit4] 2> 882850 T1871 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> 882850 T1900 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> 882850 T1916 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> 882850 T1884 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> 882850 T1864 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> 882850 T1933 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> 883331 T1842 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:31631__pe%2Fff
[junit4:junit4] 2> 883360 T1842 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:31631__pe%2Fff
[junit4:junit4] 2> 883363 T1864 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> 883363 T1884 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> 883363 T1900 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> 883363 T1916 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> 883363 T1933 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> 883363 T1871 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 883364 T1871 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> 883375 T1864 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 883375 T1900 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 883375 T1884 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 883375 T1916 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 883375 T1933 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 883381 T1934 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369067490457/collection1
[junit4:junit4] 2> 883381 T1934 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 883382 T1934 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 883382 T1934 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 883384 T1934 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369067490457/collection1/'
[junit4:junit4] 2> 883385 T1934 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1369067490457/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 883386 T1934 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ShardSplitTest-jetty4-1369067490457/collection1/lib/README' to classloader
[junit4:junit4] 2> 883437 T1934 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 883496 T1934 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 883598 T1934 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 883603 T1934 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 883807 T1874 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 883807 T1874 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:31621__pe%252Fff&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 884164 T1934 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 884168 T1934 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 884171 T1934 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 884176 T1934 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 884200 T1934 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 884200 T1934 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ShardSplitTest-jetty4-1369067490457/collection1/, dataDir=./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty4/
[junit4:junit4] 2> 884200 T1934 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@1734f867
[junit4:junit4] 2> 884201 T1934 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 884202 T1934 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty4
[junit4:junit4] 2> 884202 T1934 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty4/index/
[junit4:junit4] 2> 884202 T1934 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 884203 T1934 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty4/index
[junit4:junit4] 2> 884207 T1934 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@287d6a24 lockFactory=org.apache.lucene.store.NativeFSLockFactory@13f3521a),segFN=segments_1,generation=1}
[junit4:junit4] 2> 884207 T1934 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 884210 T1934 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 884211 T1934 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 884211 T1934 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 884212 T1934 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 884213 T1934 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 884213 T1934 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 884214 T1934 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 884214 T1934 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 884215 T1934 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 884231 T1934 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 884238 T1934 oass.SolrIndexSearcher.<init> Opening Searcher@f17f0c6 main
[junit4:junit4] 2> 884239 T1934 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty4/tlog
[junit4:junit4] 2> 884240 T1934 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 884240 T1934 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 884245 T1935 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@f17f0c6 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 884246 T1934 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 884247 T1934 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 884355 T1865 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 884356 T1865 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:31631__pe%2Fff",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:31631/_pe/ff"}
[junit4:junit4] 2> 884356 T1865 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 884357 T1865 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 884370 T1864 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> 884370 T1900 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> 884370 T1884 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> 884370 T1916 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> 884370 T1933 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> 884370 T1871 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> 885249 T1934 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 885249 T1934 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:31631/_pe/ff collection:collection1 shard:shard2
[junit4:junit4] 2> 885278 T1934 oasc.ZkController.register We are http://127.0.0.1:31631/_pe/ff/collection1/ and leader is http://127.0.0.1:46856/_pe/ff/collection1/
[junit4:junit4] 2> 885278 T1934 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:31631/_pe/ff
[junit4:junit4] 2> 885278 T1934 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 885279 T1934 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C132 name=collection1 org.apache.solr.core.SolrCore@193c1783 url=http://127.0.0.1:31631/_pe/ff/collection1 node=127.0.0.1:31631__pe%2Fff C132_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:31631__pe%2Fff, base_url=http://127.0.0.1:31631/_pe/ff}
[junit4:junit4] 2> 885279 T1936 C132 P31631 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 885280 T1934 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 885280 T1936 C132 P31631 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 885281 T1936 C132 P31631 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 885281 T1936 C132 P31631 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 885282 T1842 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 885283 T1842 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 885283 T1936 C132 P31631 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 885283 T1842 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 885308 T1842 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 885309 T1890 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 885309 T1842 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 885310 T1842 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 885311 T1842 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C131_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:31621__pe%2Fff, base_url=http://127.0.0.1:31621/_pe/ff}
[junit4:junit4] 2> 885809 T1919 C131 P31621 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:19750/_pe/ff/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 885809 T1919 C131 P31621 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:31621/_pe/ff START replicas=[http://127.0.0.1:19750/_pe/ff/collection1/] nUpdates=100
[junit4:junit4] 2> 885810 T1919 C131 P31621 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 885811 T1919 C131 P31621 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 885811 T1919 C131 P31621 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 885811 T1919 C131 P31621 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 885812 T1919 C131 P31621 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 885812 T1919 C131 P31621 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:19750/_pe/ff/collection1/. core=collection1
[junit4:junit4] 2> 885812 T1919 C131 P31621 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C133 name=collection1 org.apache.solr.core.SolrCore@4279db58 url=http://127.0.0.1:19750/_pe/ff/collection1 node=127.0.0.1:19750__pe%2Fff C133_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:19750__pe%2Fff, base_url=http://127.0.0.1:19750/_pe/ff, leader=true}
[junit4:junit4] 2> 885819 T1875 C133 P19750 oasc.SolrCore.execute [collection1] webapp=/_pe/ff path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 885823 T1876 C133 P19750 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 885826 T1876 C133 P19750 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a547b7a lockFactory=org.apache.lucene.store.NativeFSLockFactory@1096d1c1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 885827 T1876 C133 P19750 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 885828 T1876 C133 P19750 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a547b7a lockFactory=org.apache.lucene.store.NativeFSLockFactory@1096d1c1),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a547b7a lockFactory=org.apache.lucene.store.NativeFSLockFactory@1096d1c1),segFN=segments_2,generation=2}
[junit4:junit4] 2> 885828 T1876 C133 P19750 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 885829 T1876 C133 P19750 oass.SolrIndexSearcher.<init> Opening Searcher@26123cac realtime
[junit4:junit4] 2> 885829 T1876 C133 P19750 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 885830 T1876 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 885831 T1919 C131 P31621 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 885831 T1919 C131 P31621 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 885833 T1877 C133 P19750 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 885834 T1877 C133 P19750 oasc.SolrCore.execute [collection1] webapp=/_pe/ff path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 885834 T1919 C131 P31621 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 885835 T1919 C131 P31621 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 885835 T1919 C131 P31621 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 885837 T1877 C133 P19750 oasc.SolrCore.execute [collection1] webapp=/_pe/ff path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 885838 T1919 C131 P31621 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 885839 T1919 C131 P31621 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty3/index.20130520113134492
[junit4:junit4] 2> 885839 T1919 C131 P31621 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@490a0a75 lockFactory=org.apache.lucene.store.NativeFSLockFactory@395cd001) fullCopy=false
[junit4:junit4] 2> 885842 T1877 C133 P19750 oasc.SolrCore.execute [collection1] webapp=/_pe/ff path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 885843 T1919 C131 P31621 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 885844 T1919 C131 P31621 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 885845 T1919 C131 P31621 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 885847 T1919 C131 P31621 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@34c7a165 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44bc2057),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@34c7a165 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44bc2057),segFN=segments_2,generation=2}
[junit4:junit4] 2> 885847 T1919 C131 P31621 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 885847 T1919 C131 P31621 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 885848 T1919 C131 P31621 oass.SolrIndexSearcher.<init> Opening Searcher@320e57aa main
[junit4:junit4] 2> 885849 T1918 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@320e57aa main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 885849 T1919 C131 P31621 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty3/index.20130520113134492 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty3/index.20130520113134492;done=true>>]
[junit4:junit4] 2> 885850 T1919 C131 P31621 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty3/index.20130520113134492
[junit4:junit4] 2> 885850 T1919 C131 P31621 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty3/index.20130520113134492
[junit4:junit4] 2> 885850 T1919 C131 P31621 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 885850 T1919 C131 P31621 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 885851 T1919 C131 P31621 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 885851 T1919 C131 P31621 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 885852 T1919 C131 P31621 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 885874 T1865 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 885875 T1865 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:31631__pe%2Fff",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:31631/_pe/ff"}
[junit4:junit4] 2> 885879 T1865 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:31621__pe%2Fff",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:31621/_pe/ff"}
[junit4:junit4] 2> 885891 T1871 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> 885891 T1916 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> 885891 T1900 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> 885891 T1884 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> 885891 T1933 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> 885891 T1864 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> 886311 T1890 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 886311 T1890 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:31631__pe%252Fff&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 886313 T1842 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 887315 T1842 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C132_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:31631__pe%2Fff, base_url=http://127.0.0.1:31631/_pe/ff}
[junit4:junit4] 2> 888313 T1936 C132 P31631 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:46856/_pe/ff/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 888313 T1936 C132 P31631 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:31631/_pe/ff START replicas=[http://127.0.0.1:46856/_pe/ff/collection1/] nUpdates=100
[junit4:junit4] 2> 888314 T1936 C132 P31631 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 888314 T1936 C132 P31631 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 888314 T1936 C132 P31631 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 888314 T1936 C132 P31631 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 888315 T1936 C132 P31631 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 888315 T1936 C132 P31631 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:46856/_pe/ff/collection1/. core=collection1
[junit4:junit4] 2> 888316 T1936 C132 P31631 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 888318 T1842 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C134 name=collection1 org.apache.solr.core.SolrCore@3b840500 url=http://127.0.0.1:46856/_pe/ff/collection1 node=127.0.0.1:46856__pe%2Fff C134_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:46856__pe%2Fff, base_url=http://127.0.0.1:46856/_pe/ff, leader=true}
[junit4:junit4] 2> 888323 T1891 C134 P46856 oasc.SolrCore.execute [collection1] webapp=/_pe/ff path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 888328 T1892 C134 P46856 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 888330 T1892 C134 P46856 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@df6fdcf lockFactory=org.apache.lucene.store.NativeFSLockFactory@626a80cc),segFN=segments_1,generation=1}
[junit4:junit4] 2> 888331 T1892 C134 P46856 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 888332 T1892 C134 P46856 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@df6fdcf lockFactory=org.apache.lucene.store.NativeFSLockFactory@626a80cc),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@df6fdcf lockFactory=org.apache.lucene.store.NativeFSLockFactory@626a80cc),segFN=segments_2,generation=2}
[junit4:junit4] 2> 888333 T1892 C134 P46856 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 888333 T1892 C134 P46856 oass.SolrIndexSearcher.<init> Opening Searcher@40bbe09e realtime
[junit4:junit4] 2> 888334 T1892 C134 P46856 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 888334 T1892 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff 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> 888335 T1936 C132 P31631 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 888335 T1936 C132 P31631 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 888337 T1893 C134 P46856 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 888338 T1893 C134 P46856 oasc.SolrCore.execute [collection1] webapp=/_pe/ff path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 888338 T1936 C132 P31631 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 888339 T1936 C132 P31631 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 888339 T1936 C132 P31631 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 888341 T1893 C134 P46856 oasc.SolrCore.execute [collection1] webapp=/_pe/ff path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 888342 T1936 C132 P31631 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 888343 T1936 C132 P31631 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty4/index.20130520113136996
[junit4:junit4] 2> 888343 T1936 C132 P31631 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@6f3ec76b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7bbea53d) fullCopy=false
[junit4:junit4] 2> 888346 T1893 C134 P46856 oasc.SolrCore.execute [collection1] webapp=/_pe/ff path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 888347 T1936 C132 P31631 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 888348 T1936 C132 P31631 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 888348 T1936 C132 P31631 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 888350 T1936 C132 P31631 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@287d6a24 lockFactory=org.apache.lucene.store.NativeFSLockFactory@13f3521a),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@287d6a24 lockFactory=org.apache.lucene.store.NativeFSLockFactory@13f3521a),segFN=segments_2,generation=2}
[junit4:junit4] 2> 888350 T1936 C132 P31631 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 888351 T1936 C132 P31631 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 888351 T1936 C132 P31631 oass.SolrIndexSearcher.<init> Opening Searcher@3ac4172 main
[junit4:junit4] 2> 888352 T1935 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3ac4172 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 888353 T1936 C132 P31631 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty4/index.20130520113136996 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty4/index.20130520113136996;done=true>>]
[junit4:junit4] 2> 888353 T1936 C132 P31631 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty4/index.20130520113136996
[junit4:junit4] 2> 888353 T1936 C132 P31631 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ShardSplitTest-1369067474043/jetty4/index.20130520113136996
[junit4:junit4] 2> 888353 T1936 C132 P31631 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 888354 T1936 C132 P31631 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 888354 T1936 C132 P31631 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 888354 T1936 C132 P31631 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 888364 T1936 C132 P31631 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 888907 T1865 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 888908 T1865 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:31631__pe%2Fff",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:31631/_pe/ff"}
[junit4:junit4] 2> 888919 T1871 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> 888919 T1933 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> 888919 T1916 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> 888919 T1884 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> 888919 T1900 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> 888919 T1864 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> 889321 T1842 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 889323 T1842 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C135 name=collection1 org.apache.solr.core.SolrCore@5b828f32 url=http://127.0.0.1:16142/_pe/ff/collection1 node=127.0.0.1:16142__pe%2Fff C135_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:16142__pe%2Fff, base_url=http://127.0.0.1:16142/_pe/ff, leader=true}
[junit4:junit4] 2> 889331 T1854 C135 P16142 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 889335 T1854 C135 P16142 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1325e8eb lockFactory=org.apache.lucene.store.NativeFSLockFactory@62153bf1),segFN=segments_1,generation=1}
[junit4:junit4] 2> 889335 T1854 C135 P16142 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 889336 T1854 C135 P16142 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1325e8eb lockFactory=org.apache.lucene.store.NativeFSLockFactory@62153bf1),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1325e8eb lockFactory=org.apache.lucene.store.NativeFSLockFactory@62153bf1),segFN=segments_2,generation=2}
[junit4:junit4] 2> 889337 T1854 C135 P16142 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 889337 T1854 C135 P16142 oass.SolrIndexSearcher.<init> Opening Searcher@30a8d533 main
[junit4:junit4] 2> 889338 T1854 C135 P16142 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 889339 T1868 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@30a8d533 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 889339 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 8
[junit4:junit4] 2> 889350 T1894 C134 P46856 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 889352 T1894 C134 P46856 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@df6fdcf lockFactory=org.apache.lucene.store.NativeFSLockFactory@626a80cc),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@df6fdcf lockFactory=org.apache.lucene.store.NativeFSLockFactory@626a80cc),segFN=segments_3,generation=3}
[junit4:junit4] 2> 889353 T1894 C134 P46856 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 889354 T1894 C134 P46856 oass.SolrIndexSearcher.<init> Opening Searcher@4ae016ec main
[junit4:junit4] 2> 889354 T1894 C134 P46856 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 889355 T1902 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4ae016ec main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 889355 T1894 C134 P46856 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:19750/_pe/ff/collection1/, StdNode: http://127.0.0.1:31621/_pe/ff/collection1/, StdNode: http://127.0.0.1:31631/_pe/ff/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 889358 T1878 C133 P19750 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 889360 T1878 C133 P19750 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a547b7a lockFactory=org.apache.lucene.store.NativeFSLockFactory@1096d1c1),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@a547b7a lockFactory=org.apache.lucene.store.NativeFSLockFactory@1096d1c1),segFN=segments_3,generation=3}
[junit4:junit4] 2> 889361 T1878 C133 P19750 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 889361 T1878 C133 P19750 oass.SolrIndexSearcher.<init> Opening Searcher@415c45d9 main
[junit4:junit4] 2> 889362 T1878 C133 P19750 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 889362 T1886 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@415c45d9 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 889363 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> C132_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:31631__pe%2Fff, base_url=http://127.0.0.1:31631/_pe/ff}
[junit4:junit4] 2> 889366 T1923 C132 P31631 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C131_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:31621__pe%2Fff, base_url=http://127.0.0.1:31621/_pe/ff}
[junit4:junit4] 2> 889366 T1906 C131 P31621 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 889367 T1923 C132 P31631 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@287d6a24 lockFactory=org.apache.lucene.store.NativeFSLockFactory@13f3521a),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@287d6a24 lockFactory=org.apache.lucene.store.NativeFSLockFactory@13f3521a),segFN=segments_3,generation=3}
[junit4:junit4] 2> 889368 T1906 C131 P31621 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@34c7a165 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44bc2057),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@34c7a165 lockFactory=org.apache.lucene.store.NativeFSLockFactory@44bc2057),segFN=segments_3,generation=3}
[junit4:junit4] 2> 889368 T1923 C132 P31631 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 889369 T1906 C131 P31621 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 889369 T1923 C132 P31631 oass.SolrIndexSearcher.<init> Opening Searcher@4ae976e9 main
[junit4:junit4] 2> 889370 T1906 C131 P31621 oass.SolrIndexSearcher.<init> Opening Searcher@6b5a4b07 main
[junit4:junit4] 2> 889370 T1923 C132 P31631 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 889371 T1935 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4ae976e9 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 889371 T1906 C131 P31621 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 889372 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 889371 T1918 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6b5a4b07 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 889373 T1906 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 889373 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 23
[junit4:junit4] 2> 889375 T1842 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 889378 T1879 C133 P19750 oasc.SolrCore.execute [collection1] webapp=/_pe/ff path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 889380 T1907 C131 P31621 oasc.SolrCore.execute [collection1] webapp=/_pe/ff path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 889382 T1895 C134 P46856 oasc.SolrCore.execute [collection1] webapp=/_pe/ff path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 889384 T1924 C132 P31631 oasc.SolrCore.execute [collection1] webapp=/_pe/ff path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 891390 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435571322925088768)} 0 2
[junit4:junit4] 2> 891399 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={update.distrib=FROMLEADER&_version_=-1435571322929283072&update.from=http://127.0.0.1:19750/_pe/ff/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435571322929283072)} 0 2
[junit4:junit4] 2> 891402 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={update.distrib=FROMLEADER&_version_=-1435571322933477376&update.from=http://127.0.0.1:46856/_pe/ff/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435571322933477376)} 0 1
[junit4:junit4] 2> 891403 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1435571322933477376)} 0 6
[junit4:junit4] 2> 891404 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435571322929283072)} 0 11
[junit4:junit4] 2> 891408 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[a!0 (1435571322943963136)]} 0 1
[junit4:junit4] 2> 891415 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!0 (1435571322948157440)]} 0 1
[junit4:junit4] 2> 891415 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[a!0 (1435571322948157440)]} 0 4
[junit4:junit4] 2> 891419 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[b!1 (1435571322955497472)]} 0 1
[junit4:junit4] 2> 891425 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!1 (1435571322958643200)]} 0 1
[junit4:junit4] 2> 891425 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[b!1 (1435571322958643200)]} 0 4
[junit4:junit4] 2> 891428 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[c!2 (1435571322965983232)]} 0 0
[junit4:junit4] 2> 891434 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!2 (1435571322969128960)]} 0 0
[junit4:junit4] 2> 891435 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[c!2 (1435571322969128960)]} 0 4
[junit4:junit4] 2> 891438 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[d!3 (1435571322976468992)]} 0 0
[junit4:junit4] 2> 891445 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!3 (1435571322979614720)]} 0 1
[junit4:junit4] 2> 891445 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[d!3 (1435571322979614720)]} 0 4
[junit4:junit4] 2> 891448 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[e!4 (1435571322986954752)]} 0 0
[junit4:junit4] 2> 891456 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!4 (1435571322992197632)]} 0 0
[junit4:junit4] 2> 891457 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!4 (1435571322992197632)]} 0 4
[junit4:junit4] 2> 891458 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[e!4]} 0 7
[junit4:junit4] 2> 891461 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[f!5 (1435571323000586240)]} 0 0
[junit4:junit4] 2> 891470 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!5 (1435571323006877696)]} 0 0
[junit4:junit4] 2> 891471 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!5 (1435571323006877696)]} 0 4
[junit4:junit4] 2> 891472 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[f!5]} 0 8
[junit4:junit4] 2> 891476 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[g!6 (1435571323015266304)]} 0 1
[junit4:junit4] 2> 891484 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!6 (1435571323020509184)]} 0 1
[junit4:junit4] 2> 891484 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[g!6 (1435571323020509184)]} 0 4
[junit4:junit4] 2> 891485 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[g!6]} 0 7
[junit4:junit4] 2> 891488 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[h!7 (1435571323028897792)]} 0 0
[junit4:junit4] 2> 891496 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!7 (1435571323034140672)]} 0 0
[junit4:junit4] 2> 891497 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[h!7 (1435571323034140672)]} 0 4
[junit4:junit4] 2> 891498 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[h!7]} 0 7
[junit4:junit4] 2> 891500 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[i!8 (1435571323041480704)]} 0 0
[junit4:junit4] 2> 891505 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!8 (1435571323044626432)]} 0 0
[junit4:junit4] 2> 891506 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[i!8 (1435571323044626432)]} 0 3
[junit4:junit4] 2> 891509 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[j!9 (1435571323050917888)]} 0 0
[junit4:junit4] 2> 891517 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!9 (1435571323056160768)]} 0 0
[junit4:junit4] 2> 891518 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[j!9 (1435571323056160768)]} 0 4
[junit4:junit4] 2> 891519 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[j!9]} 0 7
[junit4:junit4] 2> 891522 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[k!10 (1435571323064549376)]} 0 0
[junit4:junit4] 2> 891530 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!10 (1435571323069792256)]} 0 0
[junit4:junit4] 2> 891531 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!10 (1435571323069792256)]} 0 4
[junit4:junit4] 2> 891532 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[k!10]} 0 7
[junit4:junit4] 2> 891534 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[l!11 (1435571323077132288)]} 0 0
[junit4:junit4] 2> 891543 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!11 (1435571323082375168)]} 0 1
[junit4:junit4] 2> 891543 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!11 (1435571323082375168)]} 0 4
[junit4:junit4] 2> 891544 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[l!11]} 0 7
[junit4:junit4] 2> 891547 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[m!12 (1435571323090763776)]} 0 0
[junit4:junit4] 2> 891555 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!12 (1435571323096006656)]} 0 0
[junit4:junit4] 2> 891556 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!12 (1435571323096006656)]} 0 4
[junit4:junit4] 2> 891557 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[m!12]} 0 7
[junit4:junit4] 2> 891559 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[n!13 (1435571323103346688)]} 0 0
[junit4:junit4] 2> 891567 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!13 (1435571323108589568)]} 0 0
[junit4:junit4] 2> 891568 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[n!13 (1435571323108589568)]} 0 4
[junit4:junit4] 2> 891569 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[n!13]} 0 7
[junit4:junit4] 2> 891572 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[o!14 (1435571323116978176)]} 0 0
[junit4:junit4] 2> 891580 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!14 (1435571323122221056)]} 0 0
[junit4:junit4] 2> 891581 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[o!14 (1435571323122221056)]} 0 4
[junit4:junit4] 2> 891582 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[o!14]} 0 7
[junit4:junit4] 2> 891584 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[p!15 (1435571323129561088)]} 0 0
[junit4:junit4] 2> 891592 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!15 (1435571323134803968)]} 0 0
[junit4:junit4] 2> 891593 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!15 (1435571323134803968)]} 0 4
[junit4:junit4] 2> 891594 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[p!15]} 0 7
[junit4:junit4] 2> 891596 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[q!16 (1435571323142144000)]} 0 0
[junit4:junit4] 2> 891604 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!16 (1435571323147386880)]} 0 0
[junit4:junit4] 2> 891605 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!16 (1435571323147386880)]} 0 4
[junit4:junit4] 2> 891606 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[q!16]} 0 7
[junit4:junit4] 2> 891608 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[r!17 (1435571323154726912)]} 0 0
[junit4:junit4] 2> 891616 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!17 (1435571323159969792)]} 0 0
[junit4:junit4] 2> 891617 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!17 (1435571323159969792)]} 0 4
[junit4:junit4] 2> 891618 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[r!17]} 0 7
[junit4:junit4] 2> 891620 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[s!18 (1435571323167309824)]} 0 0
[junit4:junit4] 2> 891626 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!18 (1435571323170455552)]} 0 0
[junit4:junit4] 2> 891627 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[s!18 (1435571323170455552)]} 0 4
[junit4:junit4] 2> 891630 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[t!19 (1435571323177795584)]} 0 0
[junit4:junit4] 2> 891638 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!19 (1435571323183038464)]} 0 0
[junit4:junit4] 2> 891639 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[t!19 (1435571323183038464)]} 0 4
[junit4:junit4] 2> 891640 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[t!19]} 0 7
[junit4:junit4] 2> 891642 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[u!20 (1435571323190378496)]} 0 0
[junit4:junit4] 2> 891648 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!20 (1435571323193524224)]} 0 0
[junit4:junit4] 2> 891649 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[u!20 (1435571323193524224)]} 0 4
[junit4:junit4] 2> 891652 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[v!21 (1435571323200864256)]} 0 0
[junit4:junit4] 2> 891658 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!21 (1435571323204009984)]} 0 0
[junit4:junit4] 2> 891659 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[v!21 (1435571323204009984)]} 0 4
[junit4:junit4] 2> 891662 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[w!22 (1435571323211350016)]} 0 0
[junit4:junit4] 2> 891668 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!22 (1435571323214495744)]} 0 0
[junit4:junit4] 2> 891669 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[w!22 (1435571323214495744)]} 0 4
[junit4:junit4] 2> 891672 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[x!23 (1435571323221835776)]} 0 0
[junit4:junit4] 2> 891680 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!23 (1435571323227078656)]} 0 0
[junit4:junit4] 2> 891681 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!23 (1435571323227078656)]} 0 4
[junit4:junit4] 2> 891682 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[x!23]} 0 7
[junit4:junit4] 2> 891684 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[y!24 (1435571323234418688)]} 0 0
[junit4:junit4] 2> 891690 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!24 (1435571323237564416)]} 0 0
[junit4:junit4] 2> 891691 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[y!24 (1435571323237564416)]} 0 4
[junit4:junit4] 2> 891694 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[z!25 (1435571323244904448)]} 0 0
[junit4:junit4] 2> 891700 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!25 (1435571323248050176)]} 0 0
[junit4:junit4] 2> 891701 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[z!25 (1435571323248050176)]} 0 4
[junit4:junit4] 2> 891704 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[a!26 (1435571323255390208)]} 0 0
[junit4:junit4] 2> 891710 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!26 (1435571323258535936)]} 0 0
[junit4:junit4] 2> 891711 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[a!26 (1435571323258535936)]} 0 4
[junit4:junit4] 2> 891714 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[b!27 (1435571323265875968)]} 0 0
[junit4:junit4] 2> 891720 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!27 (1435571323269021696)]} 0 0
[junit4:junit4] 2> 891721 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[b!27 (1435571323269021696)]} 0 4
[junit4:junit4] 2> 891724 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[c!28 (1435571323276361728)]} 0 0
[junit4:junit4] 2> 891729 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!28 (1435571323279507456)]} 0 0
[junit4:junit4] 2> 891730 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[c!28 (1435571323279507456)]} 0 3
[junit4:junit4] 2> 891733 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[d!29 (1435571323285798912)]} 0 0
[junit4:junit4] 2> 891741 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!29 (1435571323291041792)]} 0 0
[junit4:junit4] 2> 891742 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!29 (1435571323291041792)]} 0 4
[junit4:junit4] 2> 891743 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[d!29]} 0 7
[junit4:junit4] 2> 891745 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[e!30 (1435571323298381824)]} 0 0
[junit4:junit4] 2> 891751 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!30 (1435571323301527552)]} 0 0
[junit4:junit4] 2> 891752 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[e!30 (1435571323301527552)]} 0 4
[junit4:junit4] 2> 891755 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[f!31 (1435571323308867584)]} 0 0
[junit4:junit4] 2> 891761 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!31 (1435571323312013312)]} 0 0
[junit4:junit4] 2> 891762 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[f!31 (1435571323312013312)]} 0 4
[junit4:junit4] 2> 891765 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[g!32 (1435571323319353344)]} 0 0
[junit4:junit4] 2> 891771 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!32 (1435571323322499072)]} 0 0
[junit4:junit4] 2> 891772 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[g!32 (1435571323322499072)]} 0 4
[junit4:junit4] 2> 891775 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[h!33 (1435571323329839104)]} 0 0
[junit4:junit4] 2> 891781 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!33 (1435571323332984832)]} 0 0
[junit4:junit4] 2> 891782 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[h!33 (1435571323332984832)]} 0 4
[junit4:junit4] 2> 891785 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[i!34 (1435571323340324864)]} 0 0
[junit4:junit4] 2> 891793 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[i!34 (1435571323345567744)]} 0 0
[junit4:junit4] 2> 891794 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[i!34 (1435571323345567744)]} 0 4
[junit4:junit4] 2> 891795 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[i!34]} 0 7
[junit4:junit4] 2> 891797 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[j!35 (1435571323352907776)]} 0 0
[junit4:junit4] 2> 891803 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[j!35 (1435571323356053504)]} 0 0
[junit4:junit4] 2> 891804 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[j!35 (1435571323356053504)]} 0 4
[junit4:junit4] 2> 891807 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[k!36 (1435571323363393536)]} 0 0
[junit4:junit4] 2> 891815 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[k!36 (1435571323368636416)]} 0 0
[junit4:junit4] 2> 891816 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[k!36 (1435571323368636416)]} 0 4
[junit4:junit4] 2> 891817 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[k!36]} 0 7
[junit4:junit4] 2> 891820 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[l!37 (1435571323377025024)]} 0 0
[junit4:junit4] 2> 891828 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[l!37 (1435571323382267904)]} 0 0
[junit4:junit4] 2> 891829 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[l!37 (1435571323382267904)]} 0 4
[junit4:junit4] 2> 891830 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[l!37]} 0 7
[junit4:junit4] 2> 891832 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[m!38 (1435571323389607936)]} 0 0
[junit4:junit4] 2> 891841 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[m!38 (1435571323394850816)]} 0 0
[junit4:junit4] 2> 891841 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[m!38 (1435571323394850816)]} 0 4
[junit4:junit4] 2> 891842 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[m!38]} 0 7
[junit4:junit4] 2> 891845 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[n!39 (1435571323403239424)]} 0 0
[junit4:junit4] 2> 891851 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[n!39 (1435571323406385152)]} 0 0
[junit4:junit4] 2> 891852 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[n!39 (1435571323406385152)]} 0 4
[junit4:junit4] 2> 891855 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[o!40 (1435571323413725184)]} 0 0
[junit4:junit4] 2> 891861 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[o!40 (1435571323416870912)]} 0 0
[junit4:junit4] 2> 891862 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[o!40 (1435571323416870912)]} 0 4
[junit4:junit4] 2> 891865 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[p!41 (1435571323424210944)]} 0 0
[junit4:junit4] 2> 891873 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[p!41 (1435571323429453824)]} 0 0
[junit4:junit4] 2> 891874 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[p!41 (1435571323429453824)]} 0 4
[junit4:junit4] 2> 891875 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[p!41]} 0 7
[junit4:junit4] 2> 891877 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[q!42 (1435571323436793856)]} 0 0
[junit4:junit4] 2> 891885 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[q!42 (1435571323442036736)]} 0 0
[junit4:junit4] 2> 891886 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[q!42 (1435571323442036736)]} 0 4
[junit4:junit4] 2> 891887 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[q!42]} 0 7
[junit4:junit4] 2> 891889 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[r!43 (1435571323449376768)]} 0 0
[junit4:junit4] 2> 891897 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[r!43 (1435571323454619648)]} 0 0
[junit4:junit4] 2> 891898 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[r!43 (1435571323454619648)]} 0 4
[junit4:junit4] 2> 891899 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[r!43]} 0 7
[junit4:junit4] 2> 891902 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[s!44 (1435571323463008256)]} 0 0
[junit4:junit4] 2> 891911 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[s!44 (1435571323469299712)]} 0 0
[junit4:junit4] 2> 891912 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[s!44 (1435571323469299712)]} 0 4
[junit4:junit4] 2> 891913 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[s!44]} 0 8
[junit4:junit4] 2> 891915 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[t!45 (1435571323476639744)]} 0 0
[junit4:junit4] 2> 891921 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[t!45 (1435571323479785472)]} 0 0
[junit4:junit4] 2> 891922 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[t!45 (1435571323479785472)]} 0 4
[junit4:junit4] 2> 891926 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[u!46 (1435571323487125504)]} 0 1
[junit4:junit4] 2> 891933 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[u!46 (1435571323492368384)]} 0 0
[junit4:junit4] 2> 891934 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[u!46 (1435571323492368384)]} 0 4
[junit4:junit4] 2> 891935 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[u!46]} 0 7
[junit4:junit4] 2> 891938 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[v!47 (1435571323500756992)]} 0 0
[junit4:junit4] 2> 891947 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[v!47 (1435571323505999872)]} 0 1
[junit4:junit4] 2> 891947 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[v!47 (1435571323505999872)]} 0 4
[junit4:junit4] 2> 891948 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[v!47]} 0 7
[junit4:junit4] 2> 891951 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[w!48 (1435571323514388480)]} 0 0
[junit4:junit4] 2> 891959 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[w!48 (1435571323519631360)]} 0 0
[junit4:junit4] 2> 891960 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[w!48 (1435571323519631360)]} 0 4
[junit4:junit4] 2> 891961 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[w!48]} 0 7
[junit4:junit4] 2> 891965 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[x!49 (1435571323528019968)]} 0 1
[junit4:junit4] 2> 891972 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[x!49 (1435571323533262848)]} 0 0
[junit4:junit4] 2> 891973 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[x!49 (1435571323533262848)]} 0 4
[junit4:junit4] 2> 891974 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[x!49]} 0 7
[junit4:junit4] 2> 891977 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[y!50 (1435571323541651456)]} 0 0
[junit4:junit4] 2> 891983 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[y!50 (1435571323544797184)]} 0 0
[junit4:junit4] 2> 891984 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[y!50 (1435571323544797184)]} 0 4
[junit4:junit4] 2> 891987 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[z!51 (1435571323552137216)]} 0 0
[junit4:junit4] 2> 891995 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[z!51 (1435571323557380096)]} 0 0
[junit4:junit4] 2> 891996 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[z!51 (1435571323557380096)]} 0 4
[junit4:junit4] 2> 891997 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[z!51]} 0 7
[junit4:junit4] 2> 892000 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[a!52 (1435571323564720128)]} 0 1
[junit4:junit4] 2> 892007 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[a!52 (1435571323569963008)]} 0 0
[junit4:junit4] 2> 892008 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[a!52 (1435571323569963008)]} 0 4
[junit4:junit4] 2> 892009 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[a!52]} 0 7
[junit4:junit4] 2> 892012 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[b!53 (1435571323578351616)]} 0 0
[junit4:junit4] 2> 892021 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[b!53 (1435571323583594496)]} 0 1
[junit4:junit4] 2> 892021 T1878 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[b!53 (1435571323583594496)]} 0 4
[junit4:junit4] 2> 892022 T1894 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[b!53]} 0 7
[junit4:junit4] 2> 892025 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[c!54 (1435571323591983104)]} 0 0
[junit4:junit4] 2> 892031 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[c!54 (1435571323595128832)]} 0 0
[junit4:junit4] 2> 892032 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[c!54 (1435571323595128832)]} 0 4
[junit4:junit4] 2> 892035 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[d!55 (1435571323602468864)]} 0 0
[junit4:junit4] 2> 892043 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[d!55 (1435571323607711744)]} 0 0
[junit4:junit4] 2> 892044 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[d!55 (1435571323607711744)]} 0 4
[junit4:junit4] 2> 892045 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[d!55]} 0 7
[junit4:junit4] 2> 892048 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[e!56 (1435571323616100352)]} 0 0
[junit4:junit4] 2> 892056 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[e!56 (1435571323621343232)]} 0 0
[junit4:junit4] 2> 892057 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[e!56 (1435571323621343232)]} 0 4
[junit4:junit4] 2> 892058 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[e!56]} 0 7
[junit4:junit4] 2> 892062 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[f!57 (1435571323629731840)]} 0 1
[junit4:junit4] 2> 892070 T1923 C132 P31631 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:46856/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[f!57 (1435571323634974720)]} 0 1
[junit4:junit4] 2> 892070 T1896 C134 P46856 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[f!57 (1435571323634974720)]} 0 4
[junit4:junit4] 2> 892071 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[f!57]} 0 7
[junit4:junit4] 2> 892074 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[g!58 (1435571323643363328)]} 0 0
[junit4:junit4] 2> 892081 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[g!58 (1435571323646509056)]} 0 1
[junit4:junit4] 2> 892081 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[g!58 (1435571323646509056)]} 0 4
[junit4:junit4] 2> 892084 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[h!59 (1435571323653849088)]} 0 0
[junit4:junit4] 2> 892090 T1908 C131 P31621 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={distrib.from=http://127.0.0.1:19750/_pe/ff/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[h!59 (1435571323656994816)]} 0 0
[junit4:junit4] 2> 892091 T1880 C133 P19750 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff path=/update params={wt=javabin&version=2} {add=[h!59 (1435571323656994816)]} 0 4
[junit4:junit4] 2> 892094 T1854 C135 P16142 oasup.LogUpdateProcessor.finish [collection1] webapp=/_pe/ff
[...truncated too long message...]
17 T2039 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> 1145717 T2039 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1145717 T2039 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1145718 T1965 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/mp/aq,null}
[junit4:junit4] 2> 1145719 T2056 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1145721 T2056 oasc.Overseer.start Overseer (id=89723210386702348-127.0.0.1:37851_mp%2Faq-n_0000000004) starting
[junit4:junit4] 2> 1145726 T2122 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1145726 T2056 oascc.ZkStateReader$3.process Updating live nodes... (1)
[junit4:junit4] 2> 1145727 T2056 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> 1145727 T2121 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1145771 T1965 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 37851
[junit4:junit4] 2> 1145771 T1965 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=1111140226
[junit4:junit4] 2> 1146774 T1965 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1146774 T1965 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1146777 T1965 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@3d056388
[junit4:junit4] 2> 1146778 T1965 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=4,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=785,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 1146779 T1965 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 1146779 T1965 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 1146780 T1965 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 1146782 T1965 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 1146783 T1965 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1146783 T1965 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369067541293/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369067541293/jetty4/index;done=false>>]
[junit4:junit4] 2> 1146784 T1965 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369067541293/jetty4/index
[junit4:junit4] 2> 1146785 T1965 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369067541293/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369067541293/jetty4;done=false>>]
[junit4:junit4] 2> 1146785 T1965 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369067541293/jetty4
[junit4:junit4] 2> 1146786 T2121 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89723210386702348-127.0.0.1:37851_mp%2Faq-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 1146788 T1965 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/mp/aq,null}
[junit4:junit4] 2> 1146859 T1965 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1146861 T1965 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:31736 31736
[junit4:junit4] 2> 1146919 T1965 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 31739
[junit4:junit4] 2> !!!! WARNING: best effort to remove /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369067541293 FAILED !!!!!
[junit4:junit4] 2> 1146920 T1965 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1146920 T1965 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:31736 31736
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeyShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=64E59B5A18A6FC2F -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=en_ZA -Dtests.timezone=Brazil/Acre -Dtests.file.encoding=US-ASCII
[junit4:junit4] ERROR 214s J0 | ChaosMonkeyShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:52246/mp/aq returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([64E59B5A18A6FC2F:E50315426FF99C13]: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.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 1146930 T1965 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 214302 T1964 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> 1148088 T2056 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1148088 T2056 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> 1148088 T2056 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene3x, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=en_ZA, timezone=Brazil/Acre
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=1,free=242270808,total=489684992
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestCharFilters, SynonymTokenizerTest, SampleTest, NoCacheHeaderTest, TestClassNameShortening, TestFieldTypeResource, TestRandomFaceting, TestSolrXml, TestQueryUtils, TestFastLRUCache, MinimalSchemaTest, TestTrie, OpenExchangeRatesOrgProviderTest, PreAnalyzedFieldTest, AliasIntegrationTest, TestDistributedGrouping, LegacyHTMLStripCharFilterTest, UniqFieldsUpdateProcessorFactoryTest, DirectSolrSpellCheckerTest, TestRecovery, SpellCheckCollatorTest, TestAddFieldRealTimeGet, TestFieldTypeCollectionResource, TestPerFieldSimilarity, TestSystemIdResolver, StandardRequestHandlerTest, JSONWriterTest, BadCopyFieldTest, TestUniqueKeyFieldResource, TestPseudoReturnFields, ZkControllerTest, XmlUpdateRequestHandlerTest, TestPluginEnable, DocValuesTest, QueryElevationComponentTest, SpatialFilterTest, TestStressRecovery, BasicZkTest, SystemInfoHandlerTest, TestRandomDVFaceting, CurrencyFieldOpenExchangeTest, TermVectorComponentDistributedTest, ResponseLogComponentTest, DocValuesMultiTest, TestSolrQueryParserDefaultOperatorResource, RequiredFieldsTest, CacheHeaderTest, TestStressVersions, SortByFunctionTest, SliceStateUpdateTest, BasicDistributedZkTest, QueryEqualityTest, TestArbitraryIndexDir, TestRemoteStreaming, TestFaceting, TestDefaultSearchFieldResource, FileUtilsTest, TestAnalyzedSuggestions, SoftAutoCommitTest, TestDynamicFieldResource, TestBinaryResponseWriter, EchoParamsTest, SolrCoreTest, TestManagedSchema, TestSort, SliceStateTest, TestCollationKeyRangeQueries, DocumentBuilderTest, ReturnFieldsTest, TestHashPartitioner, ShardSplitTest, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J0 in 215.60s, 1 test, 1 error <<< FAILURES!
[...truncated 461 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:383: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:363: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java7/lucene/common-build.xml:887: There were test failures: 296 suites, 1234 tests, 2 errors, 27 ignored (8 assumptions)
Total time: 49 minutes 8 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure