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/16 03:48:29 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1622 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1622/
2 tests failed.
FAILED: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:15398 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:15398 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([4CA14552DE06E6C0:CD47CB4AA95986FC]: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:616)
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:679)
FAILED: junit.framework.TestSuite.org.apache.solr.update.processor.RegexBoostProcessorTest
Error Message:
Clean up static fields (in @AfterClass?), your test seems to hang on to approximately 22,137,840 bytes (threshold is 10,485,760). Field reference sizes (counted individually): - 22,751,288 bytes, protected static org.apache.solr.servlet.SolrRequestParsers org.apache.solr.update.processor.RegexBoostProcessorTest._parser - 5,256 bytes, private static org.apache.solr.update.processor.RegexpBoostProcessorFactory org.apache.solr.update.processor.RegexBoostProcessorTest.factory - 4,568 bytes, private static org.apache.solr.update.processor.RegexpBoostProcessor org.apache.solr.update.processor.RegexBoostProcessorTest.reProcessor - 856 bytes, protected static org.apache.solr.common.params.ModifiableSolrParams org.apache.solr.update.processor.RegexBoostProcessorTest.parameters - 296 bytes, protected static java.lang.String org.apache.solr.SolrTestCaseJ4.testSolrHome - 272 bytes, public static org.junit.rules.TestRule org.apache.solr.SolrTestCaseJ4.solrClassRules - 136 bytes, private static java.lang.String org.apache.solr.SolrTestCaseJ4.factoryProp - 72 bytes, private static java.lang.String org.apache.solr.SolrTestCaseJ4.coreName
Stack Trace:
junit.framework.AssertionFailedError: Clean up static fields (in @AfterClass?), your test seems to hang on to approximately 22,137,840 bytes (threshold is 10,485,760). Field reference sizes (counted individually):
- 22,751,288 bytes, protected static org.apache.solr.servlet.SolrRequestParsers org.apache.solr.update.processor.RegexBoostProcessorTest._parser
- 5,256 bytes, private static org.apache.solr.update.processor.RegexpBoostProcessorFactory org.apache.solr.update.processor.RegexBoostProcessorTest.factory
- 4,568 bytes, private static org.apache.solr.update.processor.RegexpBoostProcessor org.apache.solr.update.processor.RegexBoostProcessorTest.reProcessor
- 856 bytes, protected static org.apache.solr.common.params.ModifiableSolrParams org.apache.solr.update.processor.RegexBoostProcessorTest.parameters
- 296 bytes, protected static java.lang.String org.apache.solr.SolrTestCaseJ4.testSolrHome
- 272 bytes, public static org.junit.rules.TestRule org.apache.solr.SolrTestCaseJ4.solrClassRules
- 136 bytes, private static java.lang.String org.apache.solr.SolrTestCaseJ4.factoryProp
- 72 bytes, private static java.lang.String org.apache.solr.SolrTestCaseJ4.coreName
at __randomizedtesting.SeedInfo.seed([4CA14552DE06E6C0]:0)
at com.carrotsearch.randomizedtesting.rules.StaticFieldsInvariantRule$1.afterAlways(StaticFieldsInvariantRule.java:127)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:43)
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:679)
Build Log:
[...truncated 8719 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 271298 T695 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 271302 T695 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeyShardSplitTest-1368666933250
[junit4:junit4] 2> 271303 T695 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 271304 T696 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 271404 T695 oasc.ZkTestServer.run start zk server on port:27978
[junit4:junit4] 2> 271405 T695 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 271414 T702 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5a67acf3 name:ZooKeeperConnection Watcher:127.0.0.1:27978 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 271414 T695 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 271415 T695 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 271419 T695 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 271428 T704 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8a17663 name:ZooKeeperConnection Watcher:127.0.0.1:27978/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 271428 T695 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 271428 T695 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 271433 T695 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 271441 T695 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 271444 T695 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 271447 T695 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 271447 T695 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 271457 T695 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 271458 T695 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 271562 T695 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 271563 T695 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 271574 T695 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 271574 T695 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 271578 T695 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 271578 T695 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 271582 T695 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 271582 T695 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 271586 T695 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 271586 T695 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 271589 T695 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 271590 T695 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 271593 T695 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 271594 T695 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 271814 T695 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 271817 T695 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:60663
[junit4:junit4] 2> 271818 T695 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 271819 T695 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 271819 T695 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368666933551
[junit4:junit4] 2> 271819 T695 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368666933551/solr.xml
[junit4:junit4] 2> 271820 T695 oasc.CoreContainer.<init> New CoreContainer 748718121
[junit4:junit4] 2> 271821 T695 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368666933551/'
[junit4:junit4] 2> 271821 T695 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368666933551/'
[junit4:junit4] 2> 271968 T695 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 271968 T695 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 271969 T695 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 271969 T695 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 271970 T695 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 271970 T695 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 271971 T695 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 271971 T695 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 271972 T695 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 271972 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 271987 T695 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 271987 T695 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:27978/solr
[junit4:junit4] 2> 271988 T695 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 271989 T695 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 271992 T715 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@77d2eed9 name:ZooKeeperConnection Watcher:127.0.0.1:27978 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 271992 T695 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 271995 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 272005 T695 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 272008 T717 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2aefa457 name:ZooKeeperConnection Watcher:127.0.0.1:27978/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 272008 T695 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 272010 T695 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 272020 T695 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 272024 T695 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 272031 T695 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60663_
[junit4:junit4] 2> 272033 T695 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60663_
[junit4:junit4] 2> 272036 T695 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 272053 T695 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 272056 T695 oasc.Overseer.start Overseer (id=89696956137799683-127.0.0.1:60663_-n_0000000000) starting
[junit4:junit4] 2> 272067 T695 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 272079 T719 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 272079 T695 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 272082 T695 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 272089 T695 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 272095 T718 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 272096 T720 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368666933551/collection1
[junit4:junit4] 2> 272096 T720 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 272097 T720 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 272097 T720 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 272098 T720 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368666933551/collection1/'
[junit4:junit4] 2> 272099 T720 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368666933551/collection1/lib/README' to classloader
[junit4:junit4] 2> 272099 T720 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368666933551/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 272163 T720 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 272226 T720 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 272328 T720 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 272335 T720 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 272772 T720 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 272775 T720 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 272777 T720 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 272781 T720 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 272807 T720 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 272808 T720 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1368666933551/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/control/data/
[junit4:junit4] 2> 272808 T720 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@78497062
[junit4:junit4] 2> 272808 T720 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 272809 T720 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/control/data
[junit4:junit4] 2> 272809 T720 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/control/data/index/
[junit4:junit4] 2> 272809 T720 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 272810 T720 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/control/data/index
[junit4:junit4] 2> 272812 T720 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3fbebf70 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a8a0e4e),segFN=segments_1,generation=1}
[junit4:junit4] 2> 272812 T720 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 272814 T720 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 272814 T720 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 272815 T720 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 272815 T720 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 272816 T720 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 272816 T720 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 272816 T720 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 272816 T720 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 272817 T720 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 272822 T720 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 272830 T720 oass.SolrIndexSearcher.<init> Opening Searcher@a7f7dd0 main
[junit4:junit4] 2> 272830 T720 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/control/data/tlog
[junit4:junit4] 2> 272831 T720 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 272831 T720 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 272833 T721 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@a7f7dd0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 272834 T720 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 272834 T720 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 273600 T718 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 273600 T718 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:60663_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60663"}
[junit4:junit4] 2> 273601 T718 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 273601 T718 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 273616 T717 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> 273838 T720 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 273838 T720 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:60663 collection:control_collection shard:shard1
[junit4:junit4] 2> 273839 T720 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 273859 T720 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 273862 T720 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 273862 T720 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 273863 T720 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:60663/collection1/
[junit4:junit4] 2> 273863 T720 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 273863 T720 oasc.SyncStrategy.syncToMe http://127.0.0.1:60663/collection1/ has no replicas
[junit4:junit4] 2> 273863 T720 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:60663/collection1/
[junit4:junit4] 2> 273863 T720 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 275121 T718 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 275141 T717 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> 275198 T720 oasc.ZkController.register We are http://127.0.0.1:60663/collection1/ and leader is http://127.0.0.1:60663/collection1/
[junit4:junit4] 2> 275198 T720 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60663
[junit4:junit4] 2> 275198 T720 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 275198 T720 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 275198 T720 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 275201 T720 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 275202 T695 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 275202 T695 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 275202 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 275212 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 275214 T695 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 275216 T724 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7960123a name:ZooKeeperConnection Watcher:127.0.0.1:27978/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 275216 T695 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 275218 T695 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 275219 T695 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 275362 T695 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 275365 T695 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:15398
[junit4:junit4] 2> 275365 T695 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 275366 T695 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 275366 T695 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368666937167
[junit4:junit4] 2> 275366 T695 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368666937167/solr.xml
[junit4:junit4] 2> 275367 T695 oasc.CoreContainer.<init> New CoreContainer 1413913341
[junit4:junit4] 2> 275367 T695 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368666937167/'
[junit4:junit4] 2> 275367 T695 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368666937167/'
[junit4:junit4] 2> 275444 T695 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 275445 T695 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 275445 T695 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 275445 T695 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 275446 T695 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 275446 T695 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 275446 T695 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 275447 T695 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 275447 T695 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 275447 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 275458 T695 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 275458 T695 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:27978/solr
[junit4:junit4] 2> 275459 T695 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 275459 T695 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 275463 T735 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@40291a66 name:ZooKeeperConnection Watcher:127.0.0.1:27978 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 275463 T695 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 275477 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 275485 T695 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 275488 T737 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@79b20a36 name:ZooKeeperConnection Watcher:127.0.0.1:27978/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 275488 T695 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 275499 T695 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 276502 T695 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:15398_
[junit4:junit4] 2> 276531 T695 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:15398_
[junit4:junit4] 2> 276535 T717 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> 276536 T737 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 276536 T724 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 276537 T717 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 276543 T738 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368666937167/collection1
[junit4:junit4] 2> 276544 T738 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 276544 T738 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 276545 T738 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 276546 T738 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368666937167/collection1/'
[junit4:junit4] 2> 276547 T738 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368666937167/collection1/lib/README' to classloader
[junit4:junit4] 2> 276548 T738 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368666937167/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 276596 T738 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 276654 T738 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 276655 T718 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 276656 T718 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:60663__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:60663_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60663"}
[junit4:junit4] 2> 276669 T717 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> 276669 T724 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> 276755 T738 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 276755 T737 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> 276763 T738 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 277299 T738 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 277302 T738 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 277304 T738 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 277308 T738 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 277329 T738 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 277329 T738 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1368666937167/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty1/
[junit4:junit4] 2> 277330 T738 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@78497062
[junit4:junit4] 2> 277330 T738 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 277331 T738 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty1
[junit4:junit4] 2> 277331 T738 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty1/index/
[junit4:junit4] 2> 277331 T738 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 277331 T738 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty1/index
[junit4:junit4] 2> 277333 T738 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@76d0a86c lockFactory=org.apache.lucene.store.NativeFSLockFactory@270250a0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 277334 T738 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 277335 T738 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 277336 T738 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 277336 T738 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 277337 T738 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 277337 T738 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 277337 T738 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 277337 T738 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 277338 T738 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 277338 T738 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 277343 T738 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 277347 T738 oass.SolrIndexSearcher.<init> Opening Searcher@55c07d21 main
[junit4:junit4] 2> 277347 T738 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty1/tlog
[junit4:junit4] 2> 277348 T738 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 277348 T738 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 277351 T739 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@55c07d21 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 277352 T738 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 277352 T738 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 278173 T718 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 278174 T718 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:15398_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:15398"}
[junit4:junit4] 2> 278174 T718 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 278175 T718 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 278192 T724 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> 278192 T737 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> 278192 T717 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> 278380 T738 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 278380 T738 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:15398 collection:collection1 shard:shard1
[junit4:junit4] 2> 278381 T738 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 278399 T738 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 278410 T738 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 278411 T738 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 278411 T738 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:15398/collection1/
[junit4:junit4] 2> 278411 T738 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 278411 T738 oasc.SyncStrategy.syncToMe http://127.0.0.1:15398/collection1/ has no replicas
[junit4:junit4] 2> 278412 T738 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:15398/collection1/
[junit4:junit4] 2> 278412 T738 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 279697 T718 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 279753 T717 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> 279753 T737 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> 279753 T724 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> 279796 T738 oasc.ZkController.register We are http://127.0.0.1:15398/collection1/ and leader is http://127.0.0.1:15398/collection1/
[junit4:junit4] 2> 279796 T738 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:15398
[junit4:junit4] 2> 279796 T738 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 279796 T738 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 279797 T738 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 279799 T738 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 279800 T695 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 279801 T695 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 279801 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 280024 T695 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 280027 T695 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:28413
[junit4:junit4] 2> 280028 T695 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 280028 T695 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 280029 T695 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368666941762
[junit4:junit4] 2> 280029 T695 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368666941762/solr.xml
[junit4:junit4] 2> 280029 T695 oasc.CoreContainer.<init> New CoreContainer 1683615091
[junit4:junit4] 2> 280030 T695 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368666941762/'
[junit4:junit4] 2> 280031 T695 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368666941762/'
[junit4:junit4] 2> 280128 T695 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 280129 T695 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 280129 T695 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 280130 T695 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 280130 T695 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 280131 T695 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 280131 T695 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 280132 T695 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 280132 T695 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 280133 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 280147 T695 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 280148 T695 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:27978/solr
[junit4:junit4] 2> 280148 T695 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 280149 T695 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 280157 T751 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13c9c980 name:ZooKeeperConnection Watcher:127.0.0.1:27978 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 280158 T695 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 280172 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 280190 T695 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 280195 T753 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3d3cbbb1 name:ZooKeeperConnection Watcher:127.0.0.1:27978/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 280195 T695 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 280210 T695 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 281214 T695 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:28413_
[junit4:junit4] 2> 281259 T695 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:28413_
[junit4:junit4] 2> 281262 T724 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> 281263 T718 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 281262 T717 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> 281263 T753 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 281263 T737 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 281264 T718 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:15398__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:15398_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:15398"}
[junit4:junit4] 2> 281264 T737 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> 281264 T724 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 281279 T754 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368666941762/collection1
[junit4:junit4] 2> 281280 T754 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 281281 T724 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> 281281 T753 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> 281281 T754 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 281281 T737 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> 281282 T754 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 281284 T754 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368666941762/collection1/'
[junit4:junit4] 2> 281286 T717 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 281286 T754 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368666941762/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 281286 T717 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> 281287 T754 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368666941762/collection1/lib/README' to classloader
[junit4:junit4] 2> 281335 T754 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 281392 T754 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 281494 T754 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 281503 T754 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 282053 T754 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 282057 T754 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 282059 T754 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 282065 T754 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 282095 T754 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 282096 T754 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1368666941762/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty2/
[junit4:junit4] 2> 282096 T754 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@78497062
[junit4:junit4] 2> 282096 T754 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 282097 T754 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty2
[junit4:junit4] 2> 282098 T754 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty2/index/
[junit4:junit4] 2> 282098 T754 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 282099 T754 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty2/index
[junit4:junit4] 2> 282102 T754 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@383bd328 lockFactory=org.apache.lucene.store.NativeFSLockFactory@78aa6cbd),segFN=segments_1,generation=1}
[junit4:junit4] 2> 282102 T754 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 282105 T754 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 282105 T754 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 282106 T754 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 282106 T754 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 282107 T754 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 282107 T754 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 282107 T754 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 282108 T754 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 282108 T754 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 282116 T754 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 282122 T754 oass.SolrIndexSearcher.<init> Opening Searcher@48650005 main
[junit4:junit4] 2> 282122 T754 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty2/tlog
[junit4:junit4] 2> 282123 T754 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 282123 T754 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 282127 T755 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@48650005 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 282129 T754 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 282129 T754 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 282787 T718 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 282788 T718 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:28413_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:28413"}
[junit4:junit4] 2> 282788 T718 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 282788 T718 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 282812 T737 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> 282813 T724 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> 282813 T717 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> 282812 T753 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> 283158 T754 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 283158 T754 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:28413 collection:collection1 shard:shard2
[junit4:junit4] 2> 283159 T754 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 283177 T754 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 283186 T754 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 283186 T754 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 283186 T754 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:28413/collection1/
[junit4:junit4] 2> 283187 T754 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 283187 T754 oasc.SyncStrategy.syncToMe http://127.0.0.1:28413/collection1/ has no replicas
[junit4:junit4] 2> 283187 T754 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:28413/collection1/
[junit4:junit4] 2> 283187 T754 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 284327 T718 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 284399 T753 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> 284399 T737 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> 284399 T724 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> 284399 T717 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> 284427 T754 oasc.ZkController.register We are http://127.0.0.1:28413/collection1/ and leader is http://127.0.0.1:28413/collection1/
[junit4:junit4] 2> 284427 T754 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:28413
[junit4:junit4] 2> 284427 T754 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 284427 T754 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 284427 T754 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 284436 T754 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 284437 T695 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 284438 T695 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 284439 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 284667 T695 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 284671 T695 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:65373
[junit4:junit4] 2> 284672 T695 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 284672 T695 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 284672 T695 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368666946401
[junit4:junit4] 2> 284673 T695 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368666946401/solr.xml
[junit4:junit4] 2> 284673 T695 oasc.CoreContainer.<init> New CoreContainer 1195846068
[junit4:junit4] 2> 284674 T695 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368666946401/'
[junit4:junit4] 2> 284675 T695 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368666946401/'
[junit4:junit4] 2> 284780 T695 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 284780 T695 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 284781 T695 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 284781 T695 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 284782 T695 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 284782 T695 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 284783 T695 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 284783 T695 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 284784 T695 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 284784 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 284801 T695 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 284802 T695 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:27978/solr
[junit4:junit4] 2> 284802 T695 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 284803 T695 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 284833 T767 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@35a1028d name:ZooKeeperConnection Watcher:127.0.0.1:27978 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 284834 T695 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 284849 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 284863 T695 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 284865 T769 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5854278 name:ZooKeeperConnection Watcher:127.0.0.1:27978/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 284865 T695 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 284878 T695 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 285881 T695 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:65373_
[junit4:junit4] 2> 285916 T695 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:65373_
[junit4:junit4] 2> 285920 T724 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> 285920 T717 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> 285920 T737 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 285920 T769 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 285920 T753 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> 285920 T737 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> 285921 T724 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 285931 T717 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 285932 T753 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 285937 T770 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368666946401/collection1
[junit4:junit4] 2> 285937 T770 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 285938 T770 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 285938 T770 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 285939 T770 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368666946401/collection1/'
[junit4:junit4] 2> 285940 T770 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368666946401/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 285940 T770 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368666946401/collection1/lib/README' to classloader
[junit4:junit4] 2> 285963 T718 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 285964 T718 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:28413__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:28413_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:28413"}
[junit4:junit4] 2> 285973 T770 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 285977 T724 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> 285977 T769 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> 285977 T717 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> 285977 T753 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> 285977 T737 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> 286013 T770 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 286114 T770 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 286120 T770 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 286523 T770 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 286526 T770 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 286527 T770 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 286531 T770 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 286555 T770 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 286555 T770 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1368666946401/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty3/
[junit4:junit4] 2> 286555 T770 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@78497062
[junit4:junit4] 2> 286556 T770 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 286557 T770 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty3
[junit4:junit4] 2> 286557 T770 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty3/index/
[junit4:junit4] 2> 286557 T770 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 286557 T770 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty3/index
[junit4:junit4] 2> 286559 T770 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ac20952 lockFactory=org.apache.lucene.store.NativeFSLockFactory@26a9e0a6),segFN=segments_1,generation=1}
[junit4:junit4] 2> 286560 T770 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 286561 T770 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 286562 T770 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 286562 T770 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 286563 T770 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 286563 T770 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 286563 T770 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 286563 T770 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 286564 T770 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 286564 T770 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 286569 T770 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 286573 T770 oass.SolrIndexSearcher.<init> Opening Searcher@484cb430 main
[junit4:junit4] 2> 286573 T770 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty3/tlog
[junit4:junit4] 2> 286574 T770 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 286574 T770 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 286578 T771 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@484cb430 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 286580 T770 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 286580 T770 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 287482 T718 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 287483 T718 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:65373_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:65373"}
[junit4:junit4] 2> 287483 T718 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 287483 T718 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 287525 T724 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> 287525 T717 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> 287525 T753 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> 287525 T769 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> 287525 T737 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> 287589 T770 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 287589 T770 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:65373 collection:collection1 shard:shard1
[junit4:junit4] 2> 287593 T770 oasc.ZkController.register We are http://127.0.0.1:65373/collection1/ and leader is http://127.0.0.1:15398/collection1/
[junit4:junit4] 2> 287593 T770 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:65373
[junit4:junit4] 2> 287594 T770 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 287594 T770 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C29 name=collection1 org.apache.solr.core.SolrCore@2270a34d url=http://127.0.0.1:65373/collection1 node=127.0.0.1:65373_ C29_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:65373_, base_url=http://127.0.0.1:65373}
[junit4:junit4] 2> 287594 T772 C29 P65373 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 287595 T770 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 287595 T772 C29 P65373 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 287596 T772 C29 P65373 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 287596 T772 C29 P65373 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 287597 T695 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 287597 T695 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 287598 T772 C29 P65373 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 287598 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 287618 T727 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:65373__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 287943 T695 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 287947 T695 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:14398
[junit4:junit4] 2> 287948 T695 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 287949 T695 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 287949 T695 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368666949564
[junit4:junit4] 2> 287950 T695 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368666949564/solr.xml
[junit4:junit4] 2> 287951 T695 oasc.CoreContainer.<init> New CoreContainer 1206956249
[junit4:junit4] 2> 287952 T695 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368666949564/'
[junit4:junit4] 2> 287953 T695 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368666949564/'
[junit4:junit4] 2> 288108 T695 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 288109 T695 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 288110 T695 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 288110 T695 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 288111 T695 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 288112 T695 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 288113 T695 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 288113 T695 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 288114 T695 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 288115 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 288138 T695 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 288139 T695 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:27978/solr
[junit4:junit4] 2> 288140 T695 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 288142 T695 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 288146 T784 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@308423ec name:ZooKeeperConnection Watcher:127.0.0.1:27978 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 288147 T695 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 288163 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 288181 T695 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 288183 T786 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7a0c9dd6 name:ZooKeeperConnection Watcher:127.0.0.1:27978/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 288184 T695 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 288196 T695 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 289030 T718 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 289031 T718 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:65373__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:65373_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:65373"}
[junit4:junit4] 2> 289048 T786 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> 289048 T737 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> 289048 T753 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> 289048 T724 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> 289048 T769 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> 289048 T717 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> 289201 T695 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:14398_
[junit4:junit4] 2> 289240 T695 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:14398_
[junit4:junit4] 2> 289305 T769 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> 289305 T717 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> 289305 T724 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> 289305 T753 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> 289306 T786 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 289305 T737 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 289306 T786 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> 289306 T737 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> 289307 T769 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 289325 T717 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 289326 T753 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 289325 T724 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 289332 T787 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368666949564/collection1
[junit4:junit4] 2> 289332 T787 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 289333 T787 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 289333 T787 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 289334 T787 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368666949564/collection1/'
[junit4:junit4] 2> 289335 T787 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368666949564/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 289336 T787 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368666949564/collection1/lib/README' to classloader
[junit4:junit4] 2> 289369 T787 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 289407 T787 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 289509 T787 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 289515 T787 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 289621 T727 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:65373__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 289621 T727 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:65373__collection1&state=recovering&nodeName=127.0.0.1:65373_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 290080 T787 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 290084 T787 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 290087 T787 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 290092 T787 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 290123 T787 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 290123 T787 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1368666949564/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty4/
[junit4:junit4] 2> 290123 T787 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@78497062
[junit4:junit4] 2> 290124 T787 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 290124 T787 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty4
[junit4:junit4] 2> 290125 T787 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty4/index/
[junit4:junit4] 2> 290125 T787 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 290126 T787 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty4/index
[junit4:junit4] 2> 290128 T787 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@48552f85 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1add52d8),segFN=segments_1,generation=1}
[junit4:junit4] 2> 290129 T787 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 290131 T787 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 290132 T787 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 290132 T787 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 290133 T787 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 290134 T787 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 290134 T787 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 290134 T787 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 290135 T787 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 290135 T787 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 290142 T787 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 290149 T787 oass.SolrIndexSearcher.<init> Opening Searcher@3633794f main
[junit4:junit4] 2> 290149 T787 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty4/tlog
[junit4:junit4] 2> 290150 T787 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 290150 T787 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 290154 T788 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3633794f main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 290156 T787 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 290156 T787 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 290554 T718 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 290554 T718 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:14398_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:14398"}
[junit4:junit4] 2> 290555 T718 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 290555 T718 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 290574 T737 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> 290574 T769 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> 290574 T753 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> 290574 T717 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> 290574 T786 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> 290574 T724 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> 291159 T787 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 291159 T787 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:14398 collection:collection1 shard:shard2
[junit4:junit4] 2> 291164 T787 oasc.ZkController.register We are http://127.0.0.1:14398/collection1/ and leader is http://127.0.0.1:28413/collection1/
[junit4:junit4] 2> 291164 T787 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:14398
[junit4:junit4] 2> 291165 T787 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 291165 T787 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C30 name=collection1 org.apache.solr.core.SolrCore@41bfa8c8 url=http://127.0.0.1:14398/collection1 node=127.0.0.1:14398_ C30_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:14398_, base_url=http://127.0.0.1:14398}
[junit4:junit4] 2> 291165 T789 C30 P14398 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 291166 T787 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 291166 T789 C30 P14398 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 291167 T789 C30 P14398 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 291167 T789 C30 P14398 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 291167 T695 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 291168 T695 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 291169 T695 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 291169 T789 C30 P14398 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 291192 T695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 291194 T743 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:14398__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 291194 T695 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 291195 T695 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 291195 T695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C29_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:65373_, base_url=http://127.0.0.1:65373}
[junit4:junit4] 2> 291623 T772 C29 P65373 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:15398/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 291623 T772 C29 P65373 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:65373 START replicas=[http://127.0.0.1:15398/collection1/] nUpdates=100
[junit4:junit4] 2> 291624 T772 C29 P65373 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 291624 T772 C29 P65373 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 291624 T772 C29 P65373 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 291624 T772 C29 P65373 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 291624 T772 C29 P65373 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 291625 T772 C29 P65373 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:15398/collection1/. core=collection1
[junit4:junit4] 2> 291625 T772 C29 P65373 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C31 name=collection1 org.apache.solr.core.SolrCore@7cbd9f51 url=http://127.0.0.1:15398/collection1 node=127.0.0.1:15398_ C31_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:15398_, base_url=http://127.0.0.1:15398, leader=true}
[junit4:junit4] 2> 291631 T728 C31 P15398 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 291634 T729 C31 P15398 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 291637 T729 C31 P15398 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@76d0a86c lockFactory=org.apache.lucene.store.NativeFSLockFactory@270250a0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 291637 T729 C31 P15398 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 291638 T729 C31 P15398 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@76d0a86c lockFactory=org.apache.lucene.store.NativeFSLockFactory@270250a0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@76d0a86c lockFactory=org.apache.lucene.store.NativeFSLockFactory@270250a0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 291638 T729 C31 P15398 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 291639 T729 C31 P15398 oass.SolrIndexSearcher.<init> Opening Searcher@794078f1 realtime
[junit4:junit4] 2> 291639 T729 C31 P15398 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 291639 T729 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 291640 T772 C29 P65373 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 291641 T772 C29 P65373 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 291643 T730 C31 P15398 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 291643 T730 C31 P15398 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 291643 T772 C29 P65373 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 291643 T772 C29 P65373 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 291644 T772 C29 P65373 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 291646 T730 C31 P15398 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 291647 T772 C29 P65373 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 291648 T772 C29 P65373 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty3/index.20130516041553594
[junit4:junit4] 2> 291648 T772 C29 P65373 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@19e502d8 lockFactory=org.apache.lucene.store.NativeFSLockFactory@6d01739b) fullCopy=false
[junit4:junit4] 2> 291651 T730 C31 P15398 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 291652 T772 C29 P65373 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 291653 T772 C29 P65373 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 291653 T772 C29 P65373 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 291654 T772 C29 P65373 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ac20952 lockFactory=org.apache.lucene.store.NativeFSLockFactory@26a9e0a6),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ac20952 lockFactory=org.apache.lucene.store.NativeFSLockFactory@26a9e0a6),segFN=segments_2,generation=2}
[junit4:junit4] 2> 291655 T772 C29 P65373 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 291655 T772 C29 P65373 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 291655 T772 C29 P65373 oass.SolrIndexSearcher.<init> Opening Searcher@2ac1105f main
[junit4:junit4] 2> 291657 T771 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2ac1105f main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 291657 T772 C29 P65373 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty3/index.20130516041553594 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty3/index.20130516041553594;done=true>>]
[junit4:junit4] 2> 291658 T772 C29 P65373 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty3/index.20130516041553594
[junit4:junit4] 2> 291658 T772 C29 P65373 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty3/index.20130516041553594
[junit4:junit4] 2> 291658 T772 C29 P65373 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 291658 T772 C29 P65373 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 291658 T772 C29 P65373 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 291658 T772 C29 P65373 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 291660 T772 C29 P65373 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 292080 T718 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 292080 T718 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:14398__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:14398_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:14398"}
[junit4:junit4] 2> 292084 T718 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:65373__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:65373_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:65373"}
[junit4:junit4] 2> 292096 T769 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> 292096 T737 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> 292096 T724 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> 292096 T753 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> 292096 T717 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> 292096 T786 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> 292195 T743 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:14398__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 292195 T743 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:14398__collection1&state=recovering&nodeName=127.0.0.1:14398_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 292197 T695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 293200 T695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C30_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:14398_, base_url=http://127.0.0.1:14398}
[junit4:junit4] 2> 294197 T789 C30 P14398 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:28413/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 294198 T789 C30 P14398 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:14398 START replicas=[http://127.0.0.1:28413/collection1/] nUpdates=100
[junit4:junit4] 2> 294198 T789 C30 P14398 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 294198 T789 C30 P14398 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 294199 T789 C30 P14398 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 294199 T789 C30 P14398 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 294199 T789 C30 P14398 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 294199 T789 C30 P14398 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:28413/collection1/. core=collection1
[junit4:junit4] 2> 294200 T789 C30 P14398 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 294202 T695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C32 name=collection1 org.apache.solr.core.SolrCore@64bbe1ee url=http://127.0.0.1:28413/collection1 node=127.0.0.1:28413_ C32_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:28413_, base_url=http://127.0.0.1:28413, leader=true}
[junit4:junit4] 2> 294208 T744 C32 P28413 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 294213 T745 C32 P28413 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 294215 T745 C32 P28413 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@383bd328 lockFactory=org.apache.lucene.store.NativeFSLockFactory@78aa6cbd),segFN=segments_1,generation=1}
[junit4:junit4] 2> 294215 T745 C32 P28413 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 294216 T745 C32 P28413 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@383bd328 lockFactory=org.apache.lucene.store.NativeFSLockFactory@78aa6cbd),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@383bd328 lockFactory=org.apache.lucene.store.NativeFSLockFactory@78aa6cbd),segFN=segments_2,generation=2}
[junit4:junit4] 2> 294217 T745 C32 P28413 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 294217 T745 C32 P28413 oass.SolrIndexSearcher.<init> Opening Searcher@106d0c0 realtime
[junit4:junit4] 2> 294218 T745 C32 P28413 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 294218 T745 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 294219 T789 C30 P14398 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 294219 T789 C30 P14398 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 294221 T746 C32 P28413 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 294221 T746 C32 P28413 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 294222 T789 C30 P14398 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 294222 T789 C30 P14398 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 294222 T789 C30 P14398 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 294226 T746 C32 P28413 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 294227 T789 C30 P14398 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 294228 T789 C30 P14398 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty4/index.20130516041556175
[junit4:junit4] 2> 294229 T789 C30 P14398 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@7fd021bc lockFactory=org.apache.lucene.store.NativeFSLockFactory@2c0e69d2) fullCopy=false
[junit4:junit4] 2> 294231 T746 C32 P28413 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=0
[junit4:junit4] 2> 294233 T789 C30 P14398 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 294234 T789 C30 P14398 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 294234 T789 C30 P14398 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 294236 T789 C30 P14398 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@48552f85 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1add52d8),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@48552f85 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1add52d8),segFN=segments_2,generation=2}
[junit4:junit4] 2> 294236 T789 C30 P14398 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 294237 T789 C30 P14398 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 294237 T789 C30 P14398 oass.SolrIndexSearcher.<init> Opening Searcher@b6edc37 main
[junit4:junit4] 2> 294238 T788 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@b6edc37 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 294239 T789 C30 P14398 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty4/index.20130516041556175 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty4/index.20130516041556175;done=true>>]
[junit4:junit4] 2> 294239 T789 C30 P14398 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty4/index.20130516041556175
[junit4:junit4] 2> 294239 T789 C30 P14398 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1368666933249/jetty4/index.20130516041556175
[junit4:junit4] 2> 294244 T789 C30 P14398 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 294244 T789 C30 P14398 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 294245 T789 C30 P14398 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 294245 T789 C30 P14398 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 294252 T789 C30 P14398 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 295113 T718 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 295114 T718 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:14398__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:14398_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:14398"}
[junit4:junit4] 2> 295136 T786 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> 295136 T717 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> 295136 T769 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> 295136 T753 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> 295136 T724 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> 295136 T737 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> 295204 T695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 295206 T695 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C33 name=collection1 org.apache.solr.core.SolrCore@6ffff277 url=http://127.0.0.1:60663/collection1 node=127.0.0.1:60663_ C33_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:60663_, base_url=http://127.0.0.1:60663, leader=true}
[junit4:junit4] 2> 295214 T707 C33 P60663 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 295217 T707 C33 P60663 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3fbebf70 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a8a0e4e),segFN=segments_1,generation=1}
[junit4:junit4] 2> 295218 T707 C33 P60663 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 295219 T707 C33 P60663 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3fbebf70 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a8a0e4e),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3fbebf70 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3a8a0e4e),segFN=segments_2,generation=2}
[junit4:junit4] 2> 295219 T707 C33 P60663 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 295220 T707 C33 P60663 oass.SolrIndexSearcher.<init> Opening Searcher@6240dc93 main
[junit4:junit4] 2> 295220 T707 C33 P60663 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 295221 T721 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6240dc93 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 295221 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 295234 T747 C32 P28413 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 295239 T747 C32 P28413 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@383bd328 lockFactory=org.apache.lucene.store.NativeFSLockFactory@78aa6cbd),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@383bd328 lockFactory=org.apache.lucene.store.NativeFSLockFactory@78aa6cbd),segFN=segments_3,generation=3}
[junit4:junit4] 2> 295240 T747 C32 P28413 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 295240 T747 C32 P28413 oass.SolrIndexSearcher.<init> Opening Searcher@23bff716 main
[junit4:junit4] 2> 295241 T747 C32 P28413 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 295242 T755 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@23bff716 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 295242 T747 C32 P28413 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:15398/collection1/, StdNode: http://127.0.0.1:65373/collection1/, StdNode: http://127.0.0.1:14398/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 295252 T731 C31 P15398 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 295254 T731 C31 P15398 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@76d0a86c lockFactory=org.apache.lucene.store.NativeFSLockFactory@270250a0),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@76d0a86c lockFactory=org.apache.lucene.store.NativeFSLockFactory@270250a0),segFN=segments_3,generation=3}
[junit4:junit4] 2> 295254 T731 C31 P15398 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 295255 T731 C31 P15398 oass.SolrIndexSearcher.<init> Opening Searcher@5f17c550 main
[junit4:junit4] 2> 295256 T731 C31 P15398 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 295256 T739 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5f17c550 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 295257 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> C30_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:14398_, base_url=http://127.0.0.1:14398}
[junit4:junit4] 2> 295259 T776 C30 P14398 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 295260 T776 C30 P14398 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@48552f85 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1add52d8),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@48552f85 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1add52d8),segFN=segments_3,generation=3}
[junit4:junit4] 2> 295261 T776 C30 P14398 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> C29_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:65373_, base_url=http://127.0.0.1:65373}
[junit4:junit4] 2> 295261 T759 C29 P65373 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 295261 T776 C30 P14398 oass.SolrIndexSearcher.<init> Opening Searcher@7c9c8a7b main
[junit4:junit4] 2> 295262 T759 C29 P65373 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ac20952 lockFactory=org.apache.lucene.store.NativeFSLockFactory@26a9e0a6),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2ac20952 lockFactory=org.apache.lucene.store.NativeFSLockFactory@26a9e0a6),segFN=segments_3,generation=3}
[junit4:junit4] 2> 295263 T759 C29 P65373 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 295262 T776 C30 P14398 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 295263 T759 C29 P65373 oass.SolrIndexSearcher.<init> Opening Searcher@4584c87f main
[junit4:junit4] 2> 295263 T788 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7c9c8a7b main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 295264 T759 C29 P65373 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 295264 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 295264 T771 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4584c87f main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 295265 T759 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 4
[junit4:junit4] 2> 295266 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 32
[junit4:junit4] 2> 295267 T695 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 295271 T732 C31 P15398 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 295274 T760 C29 P65373 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 295277 T748 C32 P28413 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 295279 T777 C30 P14398 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=0
[junit4:junit4] 2> 297290 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435151325445750784)} 0 6
[junit4:junit4] 2> 297298 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435151325452042240&update.from=http://127.0.0.1:28413/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435151325452042240)} 0 1
[junit4:junit4] 2> 297303 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435151325457285120&update.from=http://127.0.0.1:15398/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435151325457285120)} 0 2
[junit4:junit4] 2> 297305 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1435151325457285120)} 0 7
[junit4:junit4] 2> 297305 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435151325452042240)} 0 12
[junit4:junit4] 2> 297309 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1435151325468819456)]} 0 1
[junit4:junit4] 2> 297317 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1435151325471965184)]} 0 2
[junit4:junit4] 2> 297318 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1435151325471965184)]} 0 6
[junit4:junit4] 2> 297322 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1435151325482450944)]} 0 1
[junit4:junit4] 2> 297332 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1435151325488742400)]} 0 1
[junit4:junit4] 2> 297333 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1435151325488742400)]} 0 4
[junit4:junit4] 2> 297333 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1]} 0 8
[junit4:junit4] 2> 297337 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1435151325497131008)]} 0 1
[junit4:junit4] 2> 297346 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1435151325503422464)]} 0 1
[junit4:junit4] 2> 297346 T749 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[2 (1435151325503422464)]} 0 4
[junit4:junit4] 2> 297347 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2]} 0 7
[junit4:junit4] 2> 297351 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1435151325512859648)]} 0 1
[junit4:junit4] 2> 297358 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1435151325516005376)]} 0 1
[junit4:junit4] 2> 297358 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1435151325516005376)]} 0 4
[junit4:junit4] 2> 297362 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1435151325523345408)]} 0 1
[junit4:junit4] 2> 297368 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1435151325528588288)]} 0 0
[junit4:junit4] 2> 297369 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1435151325528588288)]} 0 4
[junit4:junit4] 2> 297373 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1435151325534879744)]} 0 1
[junit4:junit4] 2> 297380 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1435151325539074048)]} 0 1
[junit4:junit4] 2> 297381 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1435151325539074048)]} 0 5
[junit4:junit4] 2> 297384 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1435151325546414080)]} 0 1
[junit4:junit4] 2> 297394 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1435151325553754112)]} 0 1
[junit4:junit4] 2> 297394 T749 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[6 (1435151325553754112)]} 0 4
[junit4:junit4] 2> 297395 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6]} 0 8
[junit4:junit4] 2> 297399 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1435151325562142720)]} 0 1
[junit4:junit4] 2> 297407 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1435151325568434176)]} 0 0
[junit4:junit4] 2> 297408 T749 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[7 (1435151325568434176)]} 0 4
[junit4:junit4] 2> 297409 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7]} 0 8
[junit4:junit4] 2> 297413 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1435151325576822784)]} 0 1
[junit4:junit4] 2> 297435 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1435151325594648576)]} 0 1
[junit4:junit4] 2> 297436 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1435151325594648576)]} 0 7
[junit4:junit4] 2> 297437 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8]} 0 22
[junit4:junit4] 2> 297441 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1435151325606182912)]} 0 1
[junit4:junit4] 2> 297450 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1435151325613522944)]} 0 0
[junit4:junit4] 2> 297451 T749 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[9 (1435151325613522944)]} 0 4
[junit4:junit4] 2> 297452 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9]} 0 8
[junit4:junit4] 2> 297456 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1435151325621911552)]} 0 1
[junit4:junit4] 2> 297462 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1435151325625057280)]} 0 1
[junit4:junit4] 2> 297463 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1435151325625057280)]} 0 5
[junit4:junit4] 2> 297466 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1435151325633445888)]} 0 0
[junit4:junit4] 2> 297476 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1435151325639737344)]} 0 1
[junit4:junit4] 2> 297477 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[11 (1435151325639737344)]} 0 5
[junit4:junit4] 2> 297477 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11]} 0 8
[junit4:junit4] 2> 297481 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1435151325649174528)]} 0 1
[junit4:junit4] 2> 297491 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1435151325655465984)]} 0 0
[junit4:junit4] 2> 297492 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[12 (1435151325655465984)]} 0 5
[junit4:junit4] 2> 297493 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12]} 0 9
[junit4:junit4] 2> 297497 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1435151325664903168)]} 0 1
[junit4:junit4] 2> 297507 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1435151325672243200)]} 0 1
[junit4:junit4] 2> 297508 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[13 (1435151325672243200)]} 0 5
[junit4:junit4] 2> 297509 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13]} 0 8
[junit4:junit4] 2> 297512 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1435151325680631808)]} 0 1
[junit4:junit4] 2> 297521 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1435151325686923264)]} 0 1
[junit4:junit4] 2> 297522 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[14 (1435151325686923264)]} 0 5
[junit4:junit4] 2> 297523 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14]} 0 8
[junit4:junit4] 2> 297527 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1435151325696360448)]} 0 1
[junit4:junit4] 2> 297533 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1435151325699506176)]} 0 1
[junit4:junit4] 2> 297534 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1435151325699506176)]} 0 5
[junit4:junit4] 2> 297537 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1435151325706846208)]} 0 1
[junit4:junit4] 2> 297547 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1435151325714186240)]} 0 1
[junit4:junit4] 2> 297548 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[16 (1435151325714186240)]} 0 5
[junit4:junit4] 2> 297549 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16]} 0 9
[junit4:junit4] 2> 297553 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1435151325723623424)]} 0 1
[junit4:junit4] 2> 297558 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1435151325726769152)]} 0 0
[junit4:junit4] 2> 297559 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1435151325726769152)]} 0 4
[junit4:junit4] 2> 297563 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1435151325734109184)]} 0 1
[junit4:junit4] 2> 297573 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1435151325741449216)]} 0 1
[junit4:junit4] 2> 297573 T749 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[18 (1435151325741449216)]} 0 4
[junit4:junit4] 2> 297574 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18]} 0 8
[junit4:junit4] 2> 297577 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1435151325749837824)]} 0 0
[junit4:junit4] 2> 297586 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1435151325756129280)]} 0 0
[junit4:junit4] 2> 297587 T749 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[19 (1435151325756129280)]} 0 4
[junit4:junit4] 2> 297588 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19]} 0 8
[junit4:junit4] 2> 297591 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1435151325763469312)]} 0 1
[junit4:junit4] 2> 297599 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1435151325768712192)]} 0 1
[junit4:junit4] 2> 297600 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[20 (1435151325768712192)]} 0 5
[junit4:junit4] 2> 297601 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20]} 0 8
[junit4:junit4] 2> 297605 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1435151325778149376)]} 0 1
[junit4:junit4] 2> 297614 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1435151325784440832)]} 0 0
[junit4:junit4] 2> 297614 T749 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[21 (1435151325784440832)]} 0 4
[junit4:junit4] 2> 297615 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21]} 0 8
[junit4:junit4] 2> 297619 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1435151325792829440)]} 0 1
[junit4:junit4] 2> 297625 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1435151325795975168)]} 0 1
[junit4:junit4] 2> 297626 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1435151325795975168)]} 0 5
[junit4:junit4] 2> 297630 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1435151325804363776)]} 0 1
[junit4:junit4] 2> 297636 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1435151325807509504)]} 0 1
[junit4:junit4] 2> 297636 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1435151325807509504)]} 0 4
[junit4:junit4] 2> 297639 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1435151325814849536)]} 0 0
[junit4:junit4] 2> 297649 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1435151325821140992)]} 0 1
[junit4:junit4] 2> 297650 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[24 (1435151325821140992)]} 0 5
[junit4:junit4] 2> 297651 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24]} 0 9
[junit4:junit4] 2> 297654 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1435151325829529600)]} 0 1
[junit4:junit4] 2> 297659 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1435151325832675328)]} 0 0
[junit4:junit4] 2> 297660 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1435151325832675328)]} 0 4
[junit4:junit4] 2> 297663 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1435151325840015360)]} 0 0
[junit4:junit4] 2> 297669 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1435151325843161088)]} 0 0
[junit4:junit4] 2> 297670 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1435151325843161088)]} 0 4
[junit4:junit4] 2> 297673 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1435151325850501120)]} 0 0
[junit4:junit4] 2> 297682 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1435151325855744000)]} 0 1
[junit4:junit4] 2> 297682 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[27 (1435151325855744000)]} 0 4
[junit4:junit4] 2> 297683 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27]} 0 7
[junit4:junit4] 2> 297686 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1435151325864132608)]} 0 0
[junit4:junit4] 2> 297692 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1435151325867278336)]} 0 1
[junit4:junit4] 2> 297692 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1435151325867278336)]} 0 3
[junit4:junit4] 2> 297695 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1435151325873569792)]} 0 0
[junit4:junit4] 2> 297703 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1435151325878812672)]} 0 0
[junit4:junit4] 2> 297704 T749 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[29 (1435151325878812672)]} 0 4
[junit4:junit4] 2> 297704 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29]} 0 6
[junit4:junit4] 2> 297707 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1435151325886152704)]} 0 0
[junit4:junit4] 2> 297713 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1435151325889298432)]} 0 0
[junit4:junit4] 2> 297714 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1435151325889298432)]} 0 4
[junit4:junit4] 2> 297717 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1435151325896638464)]} 0 0
[junit4:junit4] 2> 297724 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1435151325901881344)]} 0 0
[junit4:junit4] 2> 297725 T749 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[31 (1435151325901881344)]} 0 3
[junit4:junit4] 2> 297726 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31]} 0 6
[junit4:junit4] 2> 297728 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1435151325908172800)]} 0 0
[junit4:junit4] 2> 297738 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1435151325914464256)]} 0 1
[junit4:junit4] 2> 297738 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[32 (1435151325914464256)]} 0 4
[junit4:junit4] 2> 297739 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32]} 0 8
[junit4:junit4] 2> 297742 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1435151325922852864)]} 0 0
[junit4:junit4] 2> 297748 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1435151325925998592)]} 0 0
[junit4:junit4] 2> 297749 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1435151325925998592)]} 0 4
[junit4:junit4] 2> 297752 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1435151325933338624)]} 0 0
[junit4:junit4] 2> 297759 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1435151325936484352)]} 0 1
[junit4:junit4] 2> 297759 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1435151325936484352)]} 0 4
[junit4:junit4] 2> 297762 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1435151325943824384)]} 0 0
[junit4:junit4] 2> 297768 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1435151325946970112)]} 0 1
[junit4:junit4] 2> 297768 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1435151325946970112)]} 0 3
[junit4:junit4] 2> 297771 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1435151325953261568)]} 0 0
[junit4:junit4] 2> 297780 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1435151325958504448)]} 0 1
[junit4:junit4] 2> 297781 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[36 (1435151325958504448)]} 0 5
[junit4:junit4] 2> 297782 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36]} 0 8
[junit4:junit4] 2> 297785 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1435151325967941632)]} 0 0
[junit4:junit4] 2> 297791 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1435151325971087360)]} 0 0
[junit4:junit4] 2> 297792 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1435151325971087360)]} 0 4
[junit4:junit4] 2> 297794 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1435151325977378816)]} 0 0
[junit4:junit4] 2> 297801 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1435151325980524544)]} 0 1
[junit4:junit4] 2> 297802 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1435151325980524544)]} 0 5
[junit4:junit4] 2> 297806 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1435151325988913152)]} 0 1
[junit4:junit4] 2> 297811 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1435151325992058880)]} 0 0
[junit4:junit4] 2> 297812 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1435151325992058880)]} 0 4
[junit4:junit4] 2> 297815 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1435151325999398912)]} 0 0
[junit4:junit4] 2> 297824 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1435151326004641792)]} 0 1
[junit4:junit4] 2> 297825 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[40 (1435151326004641792)]} 0 5
[junit4:junit4] 2> 297825 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40]} 0 7
[junit4:junit4] 2> 297828 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1435151326013030400)]} 0 0
[junit4:junit4] 2> 297837 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1435151326019321856)]} 0 0
[junit4:junit4] 2> 297838 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[41 (1435151326019321856)]} 0 4
[junit4:junit4] 2> 297839 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41]} 0 8
[junit4:junit4] 2> 297842 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1435151326026661888)]} 0 1
[junit4:junit4] 2> 297851 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1435151326032953344)]} 0 1
[junit4:junit4] 2> 297851 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[42 (1435151326032953344)]} 0 4
[junit4:junit4] 2> 297852 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42]} 0 8
[junit4:junit4] 2> 297854 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1435151326040293376)]} 0 0
[junit4:junit4] 2> 297861 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1435151326043439104)]} 0 1
[junit4:junit4] 2> 297861 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1435151326043439104)]} 0 4
[junit4:junit4] 2> 297865 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1435151326050779136)]} 0 1
[junit4:junit4] 2> 297870 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1435151326053924864)]} 0 0
[junit4:junit4] 2> 297871 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1435151326053924864)]} 0 4
[junit4:junit4] 2> 297874 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1435151326061264896)]} 0 0
[junit4:junit4] 2> 297883 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1435151326067556352)]} 0 0
[junit4:junit4] 2> 297884 T749 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[45 (1435151326067556352)]} 0 4
[junit4:junit4] 2> 297885 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45]} 0 8
[junit4:junit4] 2> 297888 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1435151326075944960)]} 0 0
[junit4:junit4] 2> 297896 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1435151326081187840)]} 0 0
[junit4:junit4] 2> 297897 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[46 (1435151326081187840)]} 0 4
[junit4:junit4] 2> 297898 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46]} 0 7
[junit4:junit4] 2> 297900 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1435151326088527872)]} 0 0
[junit4:junit4] 2> 297906 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1435151326091673600)]} 0 0
[junit4:junit4] 2> 297907 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1435151326091673600)]} 0 4
[junit4:junit4] 2> 297910 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1435151326099013632)]} 0 0
[junit4:junit4] 2> 297918 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1435151326104256512)]} 0 0
[junit4:junit4] 2> 297919 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[48 (1435151326104256512)]} 0 4
[junit4:junit4] 2> 297920 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48]} 0 7
[junit4:junit4] 2> 297923 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1435151326111596544)]} 0 1
[junit4:junit4] 2> 297933 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1435151326118936576)]} 0 1
[junit4:junit4] 2> 297933 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[49 (1435151326118936576)]} 0 4
[junit4:junit4] 2> 297934 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49]} 0 8
[junit4:junit4] 2> 297938 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1435151326127325184)]} 0 1
[junit4:junit4] 2> 297946 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1435151326132568064)]} 0 1
[junit4:junit4] 2> 297946 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1435151326132568064)]} 0 5
[junit4:junit4] 2> 297950 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1435151326139908096)]} 0 1
[junit4:junit4] 2> 297959 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1435151326146199552)]} 0 1
[junit4:junit4] 2> 297959 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[51 (1435151326146199552)]} 0 4
[junit4:junit4] 2> 297960 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51]} 0 8
[junit4:junit4] 2> 297964 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1435151326154588160)]} 0 1
[junit4:junit4] 2> 297970 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1435151326158782464)]} 0 0
[junit4:junit4] 2> 297971 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1435151326158782464)]} 0 4
[junit4:junit4] 2> 297975 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1435151326166122496)]} 0 1
[junit4:junit4] 2> 297984 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1435151326172413952)]} 0 1
[junit4:junit4] 2> 297984 T749 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[53 (1435151326172413952)]} 0 4
[junit4:junit4] 2> 297985 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53]} 0 8
[junit4:junit4] 2> 297989 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1435151326180802560)]} 0 1
[junit4:junit4] 2> 297998 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1435151326187094016)]} 0 1
[junit4:junit4] 2> 297999 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[54 (1435151326187094016)]} 0 5
[junit4:junit4] 2> 297999 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54]} 0 8
[junit4:junit4] 2> 298003 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1435151326195482624)]} 0 1
[junit4:junit4] 2> 298012 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1435151326201774080)]} 0 1
[junit4:junit4] 2> 298013 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[55 (1435151326201774080)]} 0 5
[junit4:junit4] 2> 298013 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55]} 0 8
[junit4:junit4] 2> 298017 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1435151326210162688)]} 0 1
[junit4:junit4] 2> 298026 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1435151326216454144)]} 0 1
[junit4:junit4] 2> 298027 T749 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[56 (1435151326216454144)]} 0 5
[junit4:junit4] 2> 298027 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56]} 0 8
[junit4:junit4] 2> 298031 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1435151326224842752)]} 0 1
[junit4:junit4] 2> 298037 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1435151326227988480)]} 0 1
[junit4:junit4] 2> 298038 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1435151326227988480)]} 0 5
[junit4:junit4] 2> 298041 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1435151326235328512)]} 0 1
[junit4:junit4] 2> 298047 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1435151326238474240)]} 0 1
[junit4:junit4] 2> 298048 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1435151326238474240)]} 0 5
[junit4:junit4] 2> 298052 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1435151326246862848)]} 0 1
[junit4:junit4] 2> 298059 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1435151326251057152)]} 0 1
[junit4:junit4] 2> 298060 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1435151326251057152)]} 0 5
[junit4:junit4] 2> 298064 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1435151326259445760)]} 0 1
[junit4:junit4] 2> 298073 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1435151326266785792)]} 0 1
[junit4:junit4] 2> 298074 T749 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[60 (1435151326266785792)]} 0 5
[junit4:junit4] 2> 298074 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60]} 0 8
[junit4:junit4] 2> 298077 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1435151326274125824)]} 0 0
[junit4:junit4] 2> 298083 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1435151326277271552)]} 0 0
[junit4:junit4] 2> 298084 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1435151326277271552)]} 0 4
[junit4:junit4] 2> 298088 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1435151326284611584)]} 0 1
[junit4:junit4] 2> 298098 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[62 (1435151326291951616)]} 0 1
[junit4:junit4] 2> 298099 T749 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[62 (1435151326291951616)]} 0 5
[junit4:junit4] 2> 298100 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62]} 0 9
[junit4:junit4] 2> 298103 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1435151326300340224)]} 0 1
[junit4:junit4] 2> 298113 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[63 (1435151326307680256)]} 0 1
[junit4:junit4] 2> 298114 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[63 (1435151326307680256)]} 0 5
[junit4:junit4] 2> 298114 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63]} 0 8
[junit4:junit4] 2> 298118 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1435151326316068864)]} 0 1
[junit4:junit4] 2> 298125 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[64 (1435151326321311744)]} 0 1
[junit4:junit4] 2> 298125 T733 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1435151326321311744)]} 0 4
[junit4:junit4] 2> 298129 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1435151326327603200)]} 0 1
[junit4:junit4] 2> 298138 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[65 (1435151326333894656)]} 0 1
[junit4:junit4] 2> 298139 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[65 (1435151326333894656)]} 0 5
[junit4:junit4] 2> 298139 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65]} 0 8
[junit4:junit4] 2> 298143 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1435151326342283264)]} 0 1
[junit4:junit4] 2> 298152 T761 C29 P65373 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:15398/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[66 (1435151326348574720)]} 0 1
[junit4:junit4] 2> 298153 T731 C31 P15398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[66 (1435151326348574720)]} 0 5
[junit4:junit4] 2> 298153 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66]} 0 8
[junit4:junit4] 2> 298157 T707 C33 P60663 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1435151326356963328)]} 0 1
[junit4:junit4] 2> 298163 T776 C30 P14398 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:28413/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[67 (1435151326360109056)]} 0 1
[junit4:junit4] 2> 298163 T747 C32 P28413 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=
[...truncated too long message...]
L, SOLRCONFIG-XINCLUDE.XML, SOLRCONFIG-DELPOLICY1.XML, SOLRCONFIG-SLAVE1.XML, SCHEMA-SIM.XML, SCHEMA-SNIPPET-FIELD.XML, SCHEMA-COLLATE.XML, STOP-SNOWBALL.TXT, BAD-SCHEMA-SIM-GLOBAL-VS-FT-MISMATCH.XML, PROTWORDS.TXT, SCHEMA-TRIE.XML, SOLRCONFIG_CODEC.XML, SCHEMA-SYNONYM-TOKENIZER.XML, BAD-SOLRCONFIG-INVALID-SCRIPTFILE.XML, JASUGGEST.TXT, SCHEMA-REST-LUCENE-MATCH-VERSION.XML, SCHEMA-DOCVALUESFACETING.XML, SCHEMA-TFIDF.XML, SOLRCONFIG-SCRIPT-UPDATEPROCESSOR.XML, SCHEMA-LMJELINEKMERCER.XML, PHRASESUGGEST.TXT, BAD-SOLRCONFIG-MISSING-SCRIPTFILE.XML, SOLRCONFIG-BASIC-LUCENEVERSION31.XML, BAD-SCHEMA-UNIQUEKEY-USES-DEFAULT.XML, OLD_SYNONYMS.TXT, SOLRCONFIG-DELPOLICY2.XML, XSLT, SOLRCONFIG-NATIVELOCK.XML, SOLRCONFIG-MUTABLE-MANAGED-SCHEMA.XML, BAD-SCHEMA-DUP-FIELD.XML, SOLRCONFIG-NOCACHE.XML, SCHEMA-BM25.XML, BAD-SCHEMA-SWEETSPOT-BOTH-TF.XML, ADDFIELDS.UPDATEPROCESSOR.JS, SOLRCONFIG-QUERYSENDER-NOQUERY.XML, SOLRCONFIG-ALTDIRECTORY.XML, COMPOUNDDICTIONARY.TXT, SOLRCONFIG-INDEXCONFIG.XML, BAD-CURRENCY.XML, SOLRCONFIG_PERF.XML, BAD-SCHEMA-CURRENCY-FT-BOGUS-DEFAULT-CODE.XML, SCHEMA-NOT-REQUIRED-UNIQUE-KEY.XML, BAD-SCHEMA-ANALYZER-CLASS-AND-NESTED.XML, KEEP-2.TXT, BAD-SCHEMA-UNIQUEKEY-IS-COPYFIELD-DEST.XML, SCHEMA12.XML, MAPPING-ISOLATIN1ACCENT.TXT, BAD_SOLRCONFIG.XML, BAD-SCHEMA-EXTERNAL-FILEFIELD.XML]
[junit4:junit4] 2> 928070 T1197 oass.SolrIndexSearcher.<init> Opening Searcher@64a8bd73 main
[junit4:junit4] 2> 928070 T1197 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 928070 T1197 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 928071 T1197 oashc.SpellCheckComponent.inform Initializing spell checkers
[junit4:junit4] 2> 928088 T1197 oass.DirectSolrSpellChecker.init init: {name=direct,classname=DirectSolrSpellChecker,field=lowerfilt,minQueryLength=3}
[junit4:junit4] 2> 928140 T1198 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@64a8bd73 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 928143 T1197 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 928148 T1197 oas.SolrTestCaseJ4.initCore ####initCore end
[junit4:junit4] 2> 928156 T1197 oas.SolrTestCaseJ4.setUp ###Starting testTwoRules
[junit4:junit4] 2> 928156 T1197 oas.SolrTestCaseJ4.tearDown ###Ending testTwoRules
[junit4:junit4] 2> 928159 T1197 oas.SolrTestCaseJ4.setUp ###Starting testBoostGood
[junit4:junit4] 2> 928160 T1197 oas.SolrTestCaseJ4.tearDown ###Ending testBoostGood
[junit4:junit4] 2> 928163 T1197 oas.SolrTestCaseJ4.setUp ###Starting testNoBoost
[junit4:junit4] 2> 928163 T1197 oas.SolrTestCaseJ4.tearDown ###Ending testNoBoost
[junit4:junit4] 2> 928167 T1197 oas.SolrTestCaseJ4.setUp ###Starting testDeboostOld
[junit4:junit4] 2> 928167 T1197 oas.SolrTestCaseJ4.tearDown ###Ending testDeboostOld
[junit4:junit4] 2> 928168 T1197 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 928168 T1197 oasc.CoreContainer.shutdown Shutting down CoreContainer instance=89463863
[junit4:junit4] 2> 928168 T1197 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@16af619d
[junit4:junit4] 2> 928176 T1197 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=0,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=0,cumulative_deletesById=0,cumulative_deletesByQuery=0,cumulative_errors=0}
[junit4:junit4] 2> 928177 T1197 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 928177 T1197 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 928177 T1197 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 928177 T1197 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 928178 T1197 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 928178 T1197 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./solrtest-RegexBoostProcessorTest-1368667589229/index [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./solrtest-RegexBoostProcessorTest-1368667589229/index;done=false>>]
[junit4:junit4] 2> 928178 T1197 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./solrtest-RegexBoostProcessorTest-1368667589229/index
[junit4:junit4] 2> 928178 T1197 oasc.CachingDirectoryFactory.closeCacheValue looking to close /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./solrtest-RegexBoostProcessorTest-1368667589229 [CachedDir<<refCount=0;path=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./solrtest-RegexBoostProcessorTest-1368667589229;done=false>>]
[junit4:junit4] 2> 928179 T1197 oasc.CachingDirectoryFactory.close Closing directory: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./solrtest-RegexBoostProcessorTest-1368667589229
[junit4:junit4] 2> NOTE: test params are: codec=FastCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=FAST, chunkSize=33), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=FAST, chunkSize=33)), sim=DefaultSimilarity, locale=ar_EG, timezone=Indian/Chagos
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=1,free=179264816,total=427163648
[junit4:junit4] 2> NOTE: All tests run in this JVM: [DirectUpdateHandlerOptimizeTest, FieldMutatingUpdateProcessorTest, TestSolrIndexConfig, CSVRequestHandlerTest, ChaosMonkeyNothingIsSafeTest, UUIDFieldTest, TestSearchPerf, TestPseudoReturnFields, SliceStateUpdateTest, TestExtendedDismaxParser, ZkControllerTest, TestManagedSchemaFieldResource, TestFieldTypeCollectionResource, RecoveryZkTest, TestPerFieldSimilarity, SolrInfoMBeanTest, SyncSliceTest, PrimUtilsTest, SuggesterTest, TestRandomDVFaceting, ScriptEngineTest, UpdateRequestProcessorFactoryTest, TestSolrDeletionPolicy2, QueryElevationComponentTest, AliasIntegrationTest, SuggesterFSTTest, LukeRequestHandlerTest, LegacyHTMLStripCharFilterTest, ShardRoutingTest, SpatialFilterTest, ClusterStateUpdateTest, TestIBSimilarityFactory, MoreLikeThisHandlerTest, TestReversedWildcardFilterFactory, RegexBoostProcessorTest]
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=RegexBoostProcessorTest -Dtests.seed=4CA14552DE06E6C0 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar_EG -Dtests.timezone=Indian/Chagos -Dtests.file.encoding=ISO8859-1
[junit4:junit4] ERROR 0.00s J0 | RegexBoostProcessorTest (suite) <<<
[junit4:junit4] > Throwable #1: junit.framework.AssertionFailedError: Clean up static fields (in @AfterClass?), your test seems to hang on to approximately 22,137,840 bytes (threshold is 10,485,760). Field reference sizes (counted individually):
[junit4:junit4] > - 22,751,288 bytes, protected static org.apache.solr.servlet.SolrRequestParsers org.apache.solr.update.processor.RegexBoostProcessorTest._parser
[junit4:junit4] > - 5,256 bytes, private static org.apache.solr.update.processor.RegexpBoostProcessorFactory org.apache.solr.update.processor.RegexBoostProcessorTest.factory
[junit4:junit4] > - 4,568 bytes, private static org.apache.solr.update.processor.RegexpBoostProcessor org.apache.solr.update.processor.RegexBoostProcessorTest.reProcessor
[junit4:junit4] > - 856 bytes, protected static org.apache.solr.common.params.ModifiableSolrParams org.apache.solr.update.processor.RegexBoostProcessorTest.parameters
[junit4:junit4] > - 296 bytes, protected static java.lang.String org.apache.solr.SolrTestCaseJ4.testSolrHome
[junit4:junit4] > - 272 bytes, public static org.junit.rules.TestRule org.apache.solr.SolrTestCaseJ4.solrClassRules
[junit4:junit4] > - 136 bytes, private static java.lang.String org.apache.solr.SolrTestCaseJ4.factoryProp
[junit4:junit4] > - 72 bytes, private static java.lang.String org.apache.solr.SolrTestCaseJ4.coreName
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([4CA14552DE06E6C0]:0)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:679)
[junit4:junit4] Completed on J0 in 1.81s, 4 tests, 1 failure <<< FAILURES!
[...truncated 681 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:383: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:363: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:887: There were test failures: 296 suites, 1234 tests, 1 suite-level error, 1 error, 27 ignored (8 assumptions)
Total time: 59 minutes 30 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure
Re: [JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1623 - Still Failing
Posted by Shai Erera <se...@gmail.com>.
I think this exception should be thrown only when the bytes land in the
Directory. I think that in general we buffer bytes before sending them to
the actual IndexOutput? I don't know if this is done with RAMDir too i.e.
that there isn't code out there that buffers its writes to any IndexOutput,
not caring if it's RAMFile or not.
And technically, if you have a buffer of 16K, but can only write 2K to the
underlying Directory, you shouldn't hit the exception until you actually
flush the bytes?
Adrien, not in front of the code now, but if writeBytes applies the limit,
why do we need any special logic in MDW.flush?
Shai
On Thu, May 16, 2013 at 3:45 PM, Adrien Grand <jp...@gmail.com> wrote:
> On Thu, May 16, 2013 at 1:58 PM, Robert Muir <rc...@gmail.com> wrote:
> > I dont get it. MDW wraps its IndexOutput so it "knows"... sounds like
> > the counting is off.
>
> The problem is that RAMDirectory delays the counting.
> MockDirectoryWrapper.getRecomputedActualSizeInBytes sums all the
> lengths of the existing RAMFiles to get the actual size, but
> RAMFile.length is only updated after a RAMOutputStream seek or flush.
> This means that if you write 5 bytes, then 3 bytes, RAMFile.length
> will still be 0 and then suddenly upon flush it will become 5+3=8.
>
> Using the Mock IndexOutput to track bytes is an option, but I was
> thinking it could be interesting too to see what happens with
> directories that buffer content so that the disk full exception
> happens in flush instead of writeBytes?
>
> --
> Adrien
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
> For additional commands, e-mail: dev-help@lucene.apache.org
>
>
Re: [JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1623 - Still Failing
Posted by Adrien Grand <jp...@gmail.com>.
Since the resolution of this failure doesn't look trivial (as there
are several options), I opened
https://issues.apache.org/jira/browse/LUCENE-5004.
--
Adrien
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
For additional commands, e-mail: dev-help@lucene.apache.org
Re: [JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1623 - Still Failing
Posted by Shai Erera <se...@gmail.com>.
Looking at the code, I think that today flush() cannot throw diskFullEx?
MockIO checks for diskFull in writeBytes and copyBytes, using
dir.sizeInBytes.
So I think if you limit maxSize=5 and write 4 + 4 bytes, to a Directory
with a buffer of 20 bytes, then both writeBytes will succeed (as
dir.sizeInBytes = 0).
flush() will also succeed since it only calls delegate.flush().
So I think either MDW should track its size, or MockIO track the num
written bytes?
Shai
On Thu, May 16, 2013 at 7:08 PM, Robert Muir <rc...@gmail.com> wrote:
> On Thu, May 16, 2013 at 8:45 AM, Adrien Grand <jp...@gmail.com> wrote:
>
> > Using the Mock IndexOutput to track bytes is an option, but I was
> > thinking it could be interesting too to see what happens with
> > directories that buffer content so that the disk full exception
> > happens in flush instead of writeBytes?
> >
>
> But it can easily happen in both places...
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
> For additional commands, e-mail: dev-help@lucene.apache.org
>
>
Re: [JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1623 - Still Failing
Posted by Robert Muir <rc...@gmail.com>.
On Thu, May 16, 2013 at 8:45 AM, Adrien Grand <jp...@gmail.com> wrote:
> Using the Mock IndexOutput to track bytes is an option, but I was
> thinking it could be interesting too to see what happens with
> directories that buffer content so that the disk full exception
> happens in flush instead of writeBytes?
>
But it can easily happen in both places...
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
For additional commands, e-mail: dev-help@lucene.apache.org
Re: [JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1623 - Still Failing
Posted by Adrien Grand <jp...@gmail.com>.
On Thu, May 16, 2013 at 1:58 PM, Robert Muir <rc...@gmail.com> wrote:
> I dont get it. MDW wraps its IndexOutput so it "knows"... sounds like
> the counting is off.
The problem is that RAMDirectory delays the counting.
MockDirectoryWrapper.getRecomputedActualSizeInBytes sums all the
lengths of the existing RAMFiles to get the actual size, but
RAMFile.length is only updated after a RAMOutputStream seek or flush.
This means that if you write 5 bytes, then 3 bytes, RAMFile.length
will still be 0 and then suddenly upon flush it will become 5+3=8.
Using the Mock IndexOutput to track bytes is an option, but I was
thinking it could be interesting too to see what happens with
directories that buffer content so that the disk full exception
happens in flush instead of writeBytes?
--
Adrien
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
For additional commands, e-mail: dev-help@lucene.apache.org
Re: [JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1623 - Still Failing
Posted by Robert Muir <rc...@gmail.com>.
I dont get it. MDW wraps its IndexOutput so it "knows"... sounds like
the counting is off.
On Thu, May 16, 2013 at 6:24 AM, Adrien Grand <jp...@gmail.com> wrote:
> On Thu, May 16, 2013 at 11:30 AM, Shai Erera <se...@gmail.com> wrote:
>> As long as bytes are buffered, I think it's OK to not hit disk-full... they
>> never made it to the directory yet.
>
> Good point. So the test needs to call commit right after
> IndexWriter.add(Document) to make sure flush gets called, and
> MockDirectoryWrapper.flush needs to check disk full right after
> delegate.flush?
>
> --
> Adrien
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
> For additional commands, e-mail: dev-help@lucene.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
For additional commands, e-mail: dev-help@lucene.apache.org
Re: [JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1623 - Still Failing
Posted by Adrien Grand <jp...@gmail.com>.
On Thu, May 16, 2013 at 11:30 AM, Shai Erera <se...@gmail.com> wrote:
> As long as bytes are buffered, I think it's OK to not hit disk-full... they
> never made it to the directory yet.
Good point. So the test needs to call commit right after
IndexWriter.add(Document) to make sure flush gets called, and
MockDirectoryWrapper.flush needs to check disk full right after
delegate.flush?
--
Adrien
Re: [JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1623 - Still Failing
Posted by Shai Erera <se...@gmail.com>.
I hit a similar failure with the Replicator tests, or should I say "did not
hit the expected disk full".
I added a test to TestMDW.testDiskFull (fixing copyBytes to fail on
disk-full) but I put a comment on why you need to call flush().
Basically, you should call flush to ensure that bytes are not buffered.
Especially in a test which verifies 'disk full'.
As long as bytes are buffered, I think it's OK to not hit disk-full... they
never made it to the directory yet.
Shai
On Thu, May 16, 2013 at 12:12 PM, Adrien Grand <jp...@gmail.com> wrote:
> I can reproduce this one. It seems to me that the problem is that
> MockDirectoryWrapper.getRecomputedSizeInBytes uses RAMFile.length
> although RAMFile.length is only set on flush or seek and is 0 until
> then? Should setFileLength be called after every write?
>
> On Thu, May 16, 2013 at 8:35 AM, Apache Jenkins Server
> <je...@builds.apache.org> wrote:
> > Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1623/
> >
> > 1 tests failed.
> > REGRESSION:
> org.apache.lucene.index.TestIndexWriterOnDiskFull.testImmediateDiskFull
> >
> > Error Message:
> > did not hit disk full
> >
> > Stack Trace:
> > java.lang.AssertionError: did not hit disk full
> > at
> __randomizedtesting.SeedInfo.seed([9159284DB5A0A12D:1FBA21C9A14FE9]:0)
> > at org.junit.Assert.fail(Assert.java:93)
> > at
> org.apache.lucene.index.TestIndexWriterOnDiskFull.testImmediateDiskFull(TestIndexWriterOnDiskFull.java:537)
> > 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:616)
> > 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
> 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
> 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:679)
> >
> >
> >
> >
> > Build Log:
> > [...truncated 205 lines...]
> > [junit4:junit4] Suite: org.apache.lucene.index.TestIndexWriterOnDiskFull
> > [junit4:junit4] 2> NOTE: reproduce with: ant test
> -Dtestcase=TestIndexWriterOnDiskFull -Dtests.method=testImmediateDiskFull
> -Dtests.seed=9159284DB5A0A12D -Dtests.multiplier=3 -Dtests.slow=true
> -Dtests.locale=ar -Dtests.timezone=America/Managua
> -Dtests.file.encoding=ISO8859-1
> > [junit4:junit4] FAILURE 0.51s J0 |
> TestIndexWriterOnDiskFull.testImmediateDiskFull <<<
> > [junit4:junit4] > Throwable #1: java.lang.AssertionError: did not hit
> disk full
> > [junit4:junit4] > at
> __randomizedtesting.SeedInfo.seed([9159284DB5A0A12D:1FBA21C9A14FE9]:0)
> > [junit4:junit4] > at
> org.apache.lucene.index.TestIndexWriterOnDiskFull.testImmediateDiskFull(TestIndexWriterOnDiskFull.java:537)
> > [junit4:junit4] > at java.lang.Thread.run(Thread.java:679)
> > [junit4:junit4] 2> NOTE: test params are: codec=SimpleText,
> sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {f=IB
> SPL-D3(800.0), id=DFR I(F)L1, content=DFR I(ne)2, field=DFR I(n)B1},
> locale=ar, timezone=America/Managua
> > [junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems
> Inc. 1.6.0_32 (64-bit)/cpus=16,threads=1,free=401453760,total=514064384
> > [junit4:junit4] 2> NOTE: All tests run in this JVM:
> [TestIndexWriterOnDiskFull]
> > [junit4:junit4] Completed on J0 in 3.81s, 4 tests, 1 failure <<<
> FAILURES!
> >
> > [...truncated 1161 lines...]
> > BUILD FAILED
> >
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:383:
> The following error occurred while executing this line:
> >
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:363:
> The following error occurred while executing this line:
> >
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39:
> The following error occurred while executing this line:
> >
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/build.xml:49:
> The following error occurred while executing this line:
> >
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1243:
> The following error occurred while executing this line:
> >
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:887:
> There were test failures: 364 suites, 2307 tests, 1 failure, 46 ignored (34
> assumptions)
> >
> > Total time: 8 minutes 32 seconds
> > Build step 'Invoke Ant' marked build as failure
> > Archiving artifacts
> > Recording test results
> > Email was triggered for: Failure
> > Sending email for trigger: Failure
> >
> >
> >
> >
> > ---------------------------------------------------------------------
> > To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
> > For additional commands, e-mail: dev-help@lucene.apache.org
>
>
>
> --
> Adrien
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
> For additional commands, e-mail: dev-help@lucene.apache.org
>
>
Re: [JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1623 - Still Failing
Posted by Adrien Grand <jp...@gmail.com>.
I can reproduce this one. It seems to me that the problem is that
MockDirectoryWrapper.getRecomputedSizeInBytes uses RAMFile.length
although RAMFile.length is only set on flush or seek and is 0 until
then? Should setFileLength be called after every write?
On Thu, May 16, 2013 at 8:35 AM, Apache Jenkins Server
<je...@builds.apache.org> wrote:
> Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1623/
>
> 1 tests failed.
> REGRESSION: org.apache.lucene.index.TestIndexWriterOnDiskFull.testImmediateDiskFull
>
> Error Message:
> did not hit disk full
>
> Stack Trace:
> java.lang.AssertionError: did not hit disk full
> at __randomizedtesting.SeedInfo.seed([9159284DB5A0A12D:1FBA21C9A14FE9]:0)
> at org.junit.Assert.fail(Assert.java:93)
> at org.apache.lucene.index.TestIndexWriterOnDiskFull.testImmediateDiskFull(TestIndexWriterOnDiskFull.java:537)
> 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:616)
> 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 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 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:679)
>
>
>
>
> Build Log:
> [...truncated 205 lines...]
> [junit4:junit4] Suite: org.apache.lucene.index.TestIndexWriterOnDiskFull
> [junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestIndexWriterOnDiskFull -Dtests.method=testImmediateDiskFull -Dtests.seed=9159284DB5A0A12D -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar -Dtests.timezone=America/Managua -Dtests.file.encoding=ISO8859-1
> [junit4:junit4] FAILURE 0.51s J0 | TestIndexWriterOnDiskFull.testImmediateDiskFull <<<
> [junit4:junit4] > Throwable #1: java.lang.AssertionError: did not hit disk full
> [junit4:junit4] > at __randomizedtesting.SeedInfo.seed([9159284DB5A0A12D:1FBA21C9A14FE9]:0)
> [junit4:junit4] > at org.apache.lucene.index.TestIndexWriterOnDiskFull.testImmediateDiskFull(TestIndexWriterOnDiskFull.java:537)
> [junit4:junit4] > at java.lang.Thread.run(Thread.java:679)
> [junit4:junit4] 2> NOTE: test params are: codec=SimpleText, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {f=IB SPL-D3(800.0), id=DFR I(F)L1, content=DFR I(ne)2, field=DFR I(n)B1}, locale=ar, timezone=America/Managua
> [junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=1,free=401453760,total=514064384
> [junit4:junit4] 2> NOTE: All tests run in this JVM: [TestIndexWriterOnDiskFull]
> [junit4:junit4] Completed on J0 in 3.81s, 4 tests, 1 failure <<< FAILURES!
>
> [...truncated 1161 lines...]
> BUILD FAILED
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:383: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:363: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/build.xml:49: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1243: The following error occurred while executing this line:
> /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:887: There were test failures: 364 suites, 2307 tests, 1 failure, 46 ignored (34 assumptions)
>
> Total time: 8 minutes 32 seconds
> Build step 'Invoke Ant' marked build as failure
> Archiving artifacts
> Recording test results
> Email was triggered for: Failure
> Sending email for trigger: Failure
>
>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
> For additional commands, e-mail: dev-help@lucene.apache.org
--
Adrien
---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
For additional commands, e-mail: dev-help@lucene.apache.org
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1623 - Still
Failing
Posted by Apache Jenkins Server <je...@builds.apache.org>.
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1623/
1 tests failed.
REGRESSION: org.apache.lucene.index.TestIndexWriterOnDiskFull.testImmediateDiskFull
Error Message:
did not hit disk full
Stack Trace:
java.lang.AssertionError: did not hit disk full
at __randomizedtesting.SeedInfo.seed([9159284DB5A0A12D:1FBA21C9A14FE9]:0)
at org.junit.Assert.fail(Assert.java:93)
at org.apache.lucene.index.TestIndexWriterOnDiskFull.testImmediateDiskFull(TestIndexWriterOnDiskFull.java:537)
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:616)
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 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 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:679)
Build Log:
[...truncated 205 lines...]
[junit4:junit4] Suite: org.apache.lucene.index.TestIndexWriterOnDiskFull
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=TestIndexWriterOnDiskFull -Dtests.method=testImmediateDiskFull -Dtests.seed=9159284DB5A0A12D -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=ar -Dtests.timezone=America/Managua -Dtests.file.encoding=ISO8859-1
[junit4:junit4] FAILURE 0.51s J0 | TestIndexWriterOnDiskFull.testImmediateDiskFull <<<
[junit4:junit4] > Throwable #1: java.lang.AssertionError: did not hit disk full
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([9159284DB5A0A12D:1FBA21C9A14FE9]:0)
[junit4:junit4] > at org.apache.lucene.index.TestIndexWriterOnDiskFull.testImmediateDiskFull(TestIndexWriterOnDiskFull.java:537)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:679)
[junit4:junit4] 2> NOTE: test params are: codec=SimpleText, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {f=IB SPL-D3(800.0), id=DFR I(F)L1, content=DFR I(ne)2, field=DFR I(n)B1}, locale=ar, timezone=America/Managua
[junit4:junit4] 2> NOTE: FreeBSD 9.0-RELEASE amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=1,free=401453760,total=514064384
[junit4:junit4] 2> NOTE: All tests run in this JVM: [TestIndexWriterOnDiskFull]
[junit4:junit4] Completed on J0 in 3.81s, 4 tests, 1 failure <<< FAILURES!
[...truncated 1161 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:383: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:363: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/build.xml:49: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:887: There were test failures: 364 suites, 2307 tests, 1 failure, 46 ignored (34 assumptions)
Total time: 8 minutes 32 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure