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/23 03:13:57 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1648 - Still
Failing
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1648/
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:51581 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:51581 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([F905DB5F8AF4B5EB:78E35547FDABD5D7]: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)
Build Log:
[...truncated 9613 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 1642454 T3882 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 1642460 T3882 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-1369271246718
[junit4:junit4] 2> 1642462 T3882 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1642463 T3883 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1642564 T3882 oasc.ZkTestServer.run start zk server on port:40923
[junit4:junit4] 2> 1642565 T3882 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1642577 T3889 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@43bd0cab name:ZooKeeperConnection Watcher:127.0.0.1:40923 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1642578 T3882 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1642578 T3882 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1642736 T3882 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1642739 T3891 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@28c08261 name:ZooKeeperConnection Watcher:127.0.0.1:40923/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1642739 T3882 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1642740 T3882 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1642803 T3882 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1642808 T3882 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1642833 T3882 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1642862 T3882 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> 1642863 T3882 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1642945 T3882 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> 1642946 T3882 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1643058 T3882 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> 1643061 T3882 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1643066 T3882 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> 1643068 T3882 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1643074 T3882 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> 1643075 T3882 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1643079 T3882 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> 1643080 T3882 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1643084 T3882 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> 1643085 T3882 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1643089 T3882 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> 1643090 T3882 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1643093 T3882 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> 1643094 T3882 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1643381 T3882 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1643456 T3882 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:55777
[junit4:junit4] 2> 1643457 T3882 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1643458 T3882 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1643458 T3882 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-1369271247354
[junit4:junit4] 2> 1643459 T3882 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-1369271247354/solr.xml
[junit4:junit4] 2> 1643459 T3882 oasc.CoreContainer.<init> New CoreContainer 227396668
[junit4:junit4] 2> 1643460 T3882 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-1369271247354/'
[junit4:junit4] 2> 1643460 T3882 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-1369271247354/'
[junit4:junit4] 2> 1643580 T3882 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1643580 T3882 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1643581 T3882 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1643581 T3882 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1643582 T3882 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1643582 T3882 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1643583 T3882 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1643584 T3882 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1643584 T3882 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1643585 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1643600 T3882 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1643601 T3882 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:40923/solr
[junit4:junit4] 2> 1643602 T3882 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1643603 T3882 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1643610 T3902 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5eb34552 name:ZooKeeperConnection Watcher:127.0.0.1:40923 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1643611 T3882 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1643614 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1643626 T3882 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1643629 T3904 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4bcf9056 name:ZooKeeperConnection Watcher:127.0.0.1:40923/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1643629 T3882 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1643641 T3882 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1643645 T3882 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1643655 T3882 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1643657 T3882 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:55777_
[junit4:junit4] 2> 1643659 T3882 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:55777_
[junit4:junit4] 2> 1643669 T3882 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1643683 T3882 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1643686 T3882 oasc.Overseer.start Overseer (id=89736560425435139-127.0.0.1:55777_-n_0000000000) starting
[junit4:junit4] 2> 1643702 T3882 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1643713 T3906 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1643714 T3882 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1643718 T3882 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1643724 T3882 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1643727 T3905 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1643732 T3907 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-1369271247354/collection1
[junit4:junit4] 2> 1643732 T3907 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1643733 T3907 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1643733 T3907 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1643735 T3907 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-1369271247354/collection1/'
[junit4:junit4] 2> 1643737 T3907 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-1369271247354/collection1/lib/README' to classloader
[junit4:junit4] 2> 1643738 T3907 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-1369271247354/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1643797 T3907 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1643865 T3907 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1643966 T3907 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1643976 T3907 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1644588 T3907 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1644592 T3907 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1644595 T3907 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1644600 T3907 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1644622 T3907 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1644622 T3907 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-1369271247354/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/control/data/
[junit4:junit4] 2> 1644623 T3907 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@40158291
[junit4:junit4] 2> 1644623 T3907 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1644624 T3907 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/control/data
[junit4:junit4] 2> 1644624 T3907 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/control/data/index/
[junit4:junit4] 2> 1644624 T3907 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1644626 T3907 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/control/data/index
[junit4:junit4] 2> 1644632 T3907 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232415tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@492631c0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1644632 T3907 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1644635 T3907 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1644635 T3907 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1644636 T3907 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1644636 T3907 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1644637 T3907 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1644637 T3907 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1644637 T3907 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1644638 T3907 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1644638 T3907 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1644648 T3907 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1644657 T3907 oass.SolrIndexSearcher.<init> Opening Searcher@3bc7510d main
[junit4:junit4] 2> 1644657 T3907 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/control/data/tlog
[junit4:junit4] 2> 1644659 T3907 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1644659 T3907 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1644662 T3908 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3bc7510d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1644663 T3907 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1644663 T3907 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1645230 T3905 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1645231 T3905 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55777_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55777"}
[junit4:junit4] 2> 1645231 T3905 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1645232 T3905 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1645249 T3904 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> 1645666 T3907 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1645666 T3907 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:55777 collection:control_collection shard:shard1
[junit4:junit4] 2> 1645667 T3907 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1645683 T3907 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1645685 T3907 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1645685 T3907 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1645686 T3907 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:55777/collection1/
[junit4:junit4] 2> 1645686 T3907 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1645686 T3907 oasc.SyncStrategy.syncToMe http://127.0.0.1:55777/collection1/ has no replicas
[junit4:junit4] 2> 1645686 T3907 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:55777/collection1/
[junit4:junit4] 2> 1645687 T3907 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1646753 T3905 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1646781 T3904 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> 1646814 T3907 oasc.ZkController.register We are http://127.0.0.1:55777/collection1/ and leader is http://127.0.0.1:55777/collection1/
[junit4:junit4] 2> 1646814 T3907 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:55777
[junit4:junit4] 2> 1646814 T3907 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1646815 T3907 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1646815 T3907 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1646817 T3907 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1646818 T3882 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> 1646818 T3882 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1646819 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1646836 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1646838 T3882 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1646840 T3911 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@476b7ba5 name:ZooKeeperConnection Watcher:127.0.0.1:40923/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1646841 T3882 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1646842 T3882 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1646845 T3882 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1647104 T3882 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1647107 T3882 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:51581
[junit4:junit4] 2> 1647108 T3882 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1647108 T3882 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1647109 T3882 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-1369271251102
[junit4:junit4] 2> 1647109 T3882 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-1369271251102/solr.xml
[junit4:junit4] 2> 1647110 T3882 oasc.CoreContainer.<init> New CoreContainer 192060281
[junit4:junit4] 2> 1647110 T3882 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-1369271251102/'
[junit4:junit4] 2> 1647111 T3882 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-1369271251102/'
[junit4:junit4] 2> 1647222 T3882 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1647222 T3882 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1647223 T3882 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1647223 T3882 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1647224 T3882 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1647224 T3882 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1647225 T3882 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1647225 T3882 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1647226 T3882 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1647226 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1647243 T3882 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1647244 T3882 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:40923/solr
[junit4:junit4] 2> 1647244 T3882 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1647245 T3882 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1647248 T3922 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@46c54339 name:ZooKeeperConnection Watcher:127.0.0.1:40923 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1647249 T3882 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1647252 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1647264 T3882 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1647267 T3924 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@62260cb4 name:ZooKeeperConnection Watcher:127.0.0.1:40923/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1647267 T3882 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1647278 T3882 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1648281 T3882 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51581_
[junit4:junit4] 2> 1648309 T3882 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51581_
[junit4:junit4] 2> 1648311 T3905 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1648311 T3905 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:55777_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:55777"}
[junit4:junit4] 2> 1648314 T3924 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1648314 T3911 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1648324 T3924 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> 1648324 T3911 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> 1648328 T3925 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-1369271251102/collection1
[junit4:junit4] 2> 1648329 T3925 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1648334 T3925 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1648334 T3925 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1648335 T3904 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1648335 T3904 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> 1648336 T3904 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> 1648336 T3925 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-1369271251102/collection1/'
[junit4:junit4] 2> 1648338 T3925 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-1369271251102/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1648339 T3925 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-1369271251102/collection1/lib/README' to classloader
[junit4:junit4] 2> 1648400 T3925 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1648465 T3925 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1648567 T3925 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1648577 T3925 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1649179 T3925 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1649183 T3925 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1649185 T3925 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1649191 T3925 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1649208 T3925 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1649208 T3925 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-1369271251102/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty1/
[junit4:junit4] 2> 1649209 T3925 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@40158291
[junit4:junit4] 2> 1649209 T3925 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1649210 T3925 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty1
[junit4:junit4] 2> 1649210 T3925 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty1/index/
[junit4:junit4] 2> 1649210 T3925 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1649213 T3925 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty1/index
[junit4:junit4] 2> 1649217 T3925 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232416tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@dec9e19),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1649217 T3925 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1649220 T3925 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1649220 T3925 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1649221 T3925 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1649221 T3925 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1649222 T3925 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1649222 T3925 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1649222 T3925 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1649223 T3925 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1649223 T3925 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1649232 T3925 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1649241 T3925 oass.SolrIndexSearcher.<init> Opening Searcher@5efc65a8 main
[junit4:junit4] 2> 1649241 T3925 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty1/tlog
[junit4:junit4] 2> 1649242 T3925 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1649242 T3925 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1649247 T3926 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5efc65a8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1649248 T3925 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1649249 T3925 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1649836 T3905 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1649837 T3905 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51581_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51581"}
[junit4:junit4] 2> 1649838 T3905 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 1649838 T3905 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1649851 T3924 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> 1649851 T3911 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> 1649851 T3904 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> 1650276 T3925 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1650276 T3925 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51581 collection:collection1 shard:shard1
[junit4:junit4] 2> 1650277 T3925 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 1650293 T3925 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1650305 T3925 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1650305 T3925 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1650305 T3925 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51581/collection1/
[junit4:junit4] 2> 1650306 T3925 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1650306 T3925 oasc.SyncStrategy.syncToMe http://127.0.0.1:51581/collection1/ has no replicas
[junit4:junit4] 2> 1650306 T3925 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51581/collection1/
[junit4:junit4] 2> 1650307 T3925 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1651355 T3905 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1651400 T3911 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> 1651400 T3924 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> 1651400 T3904 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> 1651441 T3925 oasc.ZkController.register We are http://127.0.0.1:51581/collection1/ and leader is http://127.0.0.1:51581/collection1/
[junit4:junit4] 2> 1651441 T3925 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51581
[junit4:junit4] 2> 1651442 T3925 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1651442 T3925 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1651442 T3925 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1651445 T3925 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1651446 T3882 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> 1651447 T3882 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1651447 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1651699 T3882 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1651703 T3882 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:32339
[junit4:junit4] 2> 1651703 T3882 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1651704 T3882 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1651704 T3882 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-1369271255717
[junit4:junit4] 2> 1651705 T3882 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-1369271255717/solr.xml
[junit4:junit4] 2> 1651705 T3882 oasc.CoreContainer.<init> New CoreContainer 1581322567
[junit4:junit4] 2> 1651706 T3882 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-1369271255717/'
[junit4:junit4] 2> 1651706 T3882 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-1369271255717/'
[junit4:junit4] 2> 1651820 T3882 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1651821 T3882 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1651821 T3882 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1651822 T3882 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1651822 T3882 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1651823 T3882 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1651823 T3882 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1651824 T3882 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1651824 T3882 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1651825 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1651839 T3882 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1651840 T3882 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:40923/solr
[junit4:junit4] 2> 1651841 T3882 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1651842 T3882 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1651844 T3938 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3b5340c7 name:ZooKeeperConnection Watcher:127.0.0.1:40923 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1651845 T3882 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1651847 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1651857 T3882 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1651859 T3940 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4ee0228f name:ZooKeeperConnection Watcher:127.0.0.1:40923/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1651859 T3882 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1651871 T3882 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1652874 T3882 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:32339_
[junit4:junit4] 2> 1652880 T3882 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:32339_
[junit4:junit4] 2> 1652884 T3924 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> 1652884 T3904 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1652884 T3911 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1652884 T3940 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1652885 T3911 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> 1652884 T3904 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> 1652885 T3924 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1652896 T3941 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-1369271255717/collection1
[junit4:junit4] 2> 1652896 T3941 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1652897 T3941 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1652897 T3941 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1652898 T3941 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-1369271255717/collection1/'
[junit4:junit4] 2> 1652900 T3941 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-1369271255717/collection1/lib/README' to classloader
[junit4:junit4] 2> 1652900 T3941 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-1369271255717/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1652906 T3905 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1652907 T3905 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51581_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51581"}
[junit4:junit4] 2> 1652916 T3904 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> 1652916 T3911 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> 1652916 T3924 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> 1652916 T3940 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> 1652954 T3941 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1653015 T3941 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1653117 T3941 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1653125 T3941 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1653732 T3941 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1653736 T3941 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1653739 T3941 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1653743 T3941 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1653761 T3941 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1653761 T3941 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-1369271255717/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty2/
[junit4:junit4] 2> 1653761 T3941 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@40158291
[junit4:junit4] 2> 1653762 T3941 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1653763 T3941 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty2
[junit4:junit4] 2> 1653763 T3941 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty2/index/
[junit4:junit4] 2> 1653763 T3941 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1653765 T3941 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty2/index
[junit4:junit4] 2> 1653769 T3941 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232417tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@6102a44b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1653770 T3941 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1653772 T3941 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1653772 T3941 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1653773 T3941 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1653774 T3941 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1653774 T3941 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1653774 T3941 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1653775 T3941 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1653775 T3941 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1653776 T3941 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1653784 T3941 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1653793 T3941 oass.SolrIndexSearcher.<init> Opening Searcher@5d7997ec main
[junit4:junit4] 2> 1653793 T3941 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty2/tlog
[junit4:junit4] 2> 1653794 T3941 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1653794 T3941 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1653798 T3942 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5d7997ec main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1653800 T3941 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1653800 T3941 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1654425 T3905 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1654426 T3905 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:32339_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:32339"}
[junit4:junit4] 2> 1654426 T3905 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1654426 T3905 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1654439 T3940 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> 1654439 T3904 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> 1654439 T3911 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> 1654439 T3924 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> 1654828 T3941 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1654828 T3941 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:32339 collection:collection1 shard:shard2
[junit4:junit4] 2> 1654829 T3941 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 1654856 T3941 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1654865 T3941 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1654865 T3941 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1654865 T3941 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:32339/collection1/
[junit4:junit4] 2> 1654866 T3941 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1654866 T3941 oasc.SyncStrategy.syncToMe http://127.0.0.1:32339/collection1/ has no replicas
[junit4:junit4] 2> 1654866 T3941 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:32339/collection1/
[junit4:junit4] 2> 1654866 T3941 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1655943 T3905 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1655960 T3911 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> 1655960 T3904 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> 1655960 T3924 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> 1655960 T3940 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> 1656002 T3941 oasc.ZkController.register We are http://127.0.0.1:32339/collection1/ and leader is http://127.0.0.1:32339/collection1/
[junit4:junit4] 2> 1656002 T3941 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:32339
[junit4:junit4] 2> 1656002 T3941 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1656002 T3941 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1656003 T3941 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1656004 T3941 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1656005 T3882 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> 1656006 T3882 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1656007 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1656298 T3882 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1656301 T3882 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:46683
[junit4:junit4] 2> 1656302 T3882 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1656303 T3882 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1656303 T3882 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-1369271260278
[junit4:junit4] 2> 1656304 T3882 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-1369271260278/solr.xml
[junit4:junit4] 2> 1656304 T3882 oasc.CoreContainer.<init> New CoreContainer 1219884343
[junit4:junit4] 2> 1656305 T3882 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-1369271260278/'
[junit4:junit4] 2> 1656305 T3882 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-1369271260278/'
[junit4:junit4] 2> 1656433 T3882 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1656434 T3882 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1656434 T3882 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1656435 T3882 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1656435 T3882 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1656436 T3882 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1656436 T3882 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1656437 T3882 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1656437 T3882 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1656438 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1656454 T3882 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1656454 T3882 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:40923/solr
[junit4:junit4] 2> 1656455 T3882 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1656456 T3882 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1656459 T3954 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2264bf1f name:ZooKeeperConnection Watcher:127.0.0.1:40923 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1656459 T3882 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1656473 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1656482 T3882 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1656484 T3956 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6b3ebe7b name:ZooKeeperConnection Watcher:127.0.0.1:40923/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1656484 T3882 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1656494 T3882 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1657473 T3905 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1657474 T3905 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:32339_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:32339"}
[junit4:junit4] 2> 1657503 T3882 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:46683_
[junit4:junit4] 2> 1657505 T3904 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> 1657505 T3940 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> 1657505 T3924 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> 1657505 T3956 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> 1657505 T3911 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> 1657543 T3882 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:46683_
[junit4:junit4] 2> 1657599 T3924 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> 1657599 T3911 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1657599 T3940 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> 1657599 T3956 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> 1657600 T3904 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1657599 T3911 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> 1657600 T3904 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> 1657602 T3924 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1657603 T3940 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1657603 T3956 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1657607 T3957 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-1369271260278/collection1
[junit4:junit4] 2> 1657608 T3957 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1657608 T3957 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1657608 T3957 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1657610 T3957 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-1369271260278/collection1/'
[junit4:junit4] 2> 1657611 T3957 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-1369271260278/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1657612 T3957 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-1369271260278/collection1/lib/README' to classloader
[junit4:junit4] 2> 1657662 T3957 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1657719 T3957 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1657821 T3957 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1657826 T3957 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1658218 T3957 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1658221 T3957 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1658225 T3957 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1658229 T3957 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1658245 T3957 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1658246 T3957 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-1369271260278/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty3/
[junit4:junit4] 2> 1658246 T3957 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@40158291
[junit4:junit4] 2> 1658246 T3957 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1658247 T3957 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty3
[junit4:junit4] 2> 1658247 T3957 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty3/index/
[junit4:junit4] 2> 1658247 T3957 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1658250 T3957 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty3/index
[junit4:junit4] 2> 1658254 T3957 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232418tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f5bda7),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1658254 T3957 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1658256 T3957 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1658256 T3957 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1658257 T3957 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1658257 T3957 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1658257 T3957 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1658258 T3957 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1658258 T3957 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1658258 T3957 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1658259 T3957 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1658268 T3957 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1658276 T3957 oass.SolrIndexSearcher.<init> Opening Searcher@42420f4c main
[junit4:junit4] 2> 1658276 T3957 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty3/tlog
[junit4:junit4] 2> 1658277 T3957 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1658277 T3957 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1658280 T3958 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@42420f4c main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1658282 T3957 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1658282 T3957 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1659081 T3905 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1659082 T3905 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46683_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46683"}
[junit4:junit4] 2> 1659082 T3905 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1659082 T3905 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1659095 T3904 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> 1659095 T3956 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> 1659095 T3940 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> 1659095 T3924 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> 1659095 T3911 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> 1659285 T3957 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1659285 T3957 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:46683 collection:collection1 shard:shard1
[junit4:junit4] 2> 1659288 T3957 oasc.ZkController.register We are http://127.0.0.1:46683/collection1/ and leader is http://127.0.0.1:51581/collection1/
[junit4:junit4] 2> 1659289 T3957 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:46683
[junit4:junit4] 2> 1659289 T3957 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1659289 T3957 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1837 name=collection1 org.apache.solr.core.SolrCore@2bdf9543 url=http://127.0.0.1:46683/collection1 node=127.0.0.1:46683_ C1837_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:46683_, base_url=http://127.0.0.1:46683}
[junit4:junit4] 2> 1659290 T3959 C1837 P46683 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1659290 T3959 C1837 P46683 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1659290 T3957 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1659290 T3959 C1837 P46683 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1659291 T3959 C1837 P46683 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1659291 T3882 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> 1659292 T3882 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1659292 T3959 C1837 P46683 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1659293 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1659312 T3914 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1659502 T3882 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1659506 T3882 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:41475
[junit4:junit4] 2> 1659507 T3882 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1659508 T3882 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1659508 T3882 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-1369271263566
[junit4:junit4] 2> 1659508 T3882 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-1369271263566/solr.xml
[junit4:junit4] 2> 1659509 T3882 oasc.CoreContainer.<init> New CoreContainer 182819518
[junit4:junit4] 2> 1659509 T3882 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-1369271263566/'
[junit4:junit4] 2> 1659510 T3882 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-1369271263566/'
[junit4:junit4] 2> 1659612 T3882 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1659613 T3882 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1659613 T3882 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1659614 T3882 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1659614 T3882 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1659615 T3882 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1659615 T3882 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1659616 T3882 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1659616 T3882 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1659617 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1659634 T3882 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1659635 T3882 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:40923/solr
[junit4:junit4] 2> 1659636 T3882 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1659638 T3882 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1659640 T3971 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@378a919 name:ZooKeeperConnection Watcher:127.0.0.1:40923 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1659641 T3882 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1659643 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1659651 T3882 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1659654 T3973 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7ab68280 name:ZooKeeperConnection Watcher:127.0.0.1:40923/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1659654 T3882 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1659666 T3882 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1660600 T3905 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1660601 T3905 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46683_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46683"}
[junit4:junit4] 2> 1660613 T3911 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> 1660614 T3940 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> 1660614 T3973 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> 1660613 T3956 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> 1660614 T3924 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> 1660613 T3904 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> 1660669 T3882 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:41475_
[junit4:junit4] 2> 1660671 T3882 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:41475_
[junit4:junit4] 2> 1660673 T3956 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> 1660674 T3911 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1660674 T3973 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1660674 T3904 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1660674 T3940 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> 1660674 T3924 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> 1660675 T3956 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1660674 T3904 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> 1660674 T3973 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> 1660674 T3911 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> 1660683 T3924 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1660683 T3940 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1660686 T3974 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-1369271263566/collection1
[junit4:junit4] 2> 1660687 T3974 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1660687 T3974 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1660687 T3974 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1660689 T3974 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-1369271263566/collection1/'
[junit4:junit4] 2> 1660690 T3974 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-1369271263566/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1660691 T3974 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-1369271263566/collection1/lib/README' to classloader
[junit4:junit4] 2> 1660742 T3974 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1660800 T3974 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1660902 T3974 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1660909 T3974 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1661314 T3914 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1661314 T3914 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:46683_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 1661449 T3974 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1661453 T3974 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1661456 T3974 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1661461 T3974 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1661483 T3974 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1661483 T3974 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-1369271263566/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4/
[junit4:junit4] 2> 1661484 T3974 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@40158291
[junit4:junit4] 2> 1661484 T3974 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1661485 T3974 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4
[junit4:junit4] 2> 1661485 T3974 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4/index/
[junit4:junit4] 2> 1661485 T3974 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1661488 T3974 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4/index
[junit4:junit4] 2> 1661493 T3974 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232419tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@37f21d44),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1661493 T3974 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1661496 T3974 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1661497 T3974 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1661497 T3974 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1661498 T3974 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1661498 T3974 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1661499 T3974 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1661499 T3974 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1661500 T3974 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1661500 T3974 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1661510 T3974 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1661519 T3974 oass.SolrIndexSearcher.<init> Opening Searcher@61862719 main
[junit4:junit4] 2> 1661519 T3974 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4/tlog
[junit4:junit4] 2> 1661520 T3974 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1661521 T3974 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1661525 T3975 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@61862719 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1661527 T3974 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1661528 T3974 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1662119 T3905 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1662120 T3905 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:41475_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41475"}
[junit4:junit4] 2> 1662120 T3905 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1662121 T3905 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1662134 T3911 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> 1662134 T3904 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> 1662134 T3924 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> 1662134 T3973 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> 1662134 T3940 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> 1662134 T3956 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> 1662530 T3974 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1662530 T3974 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:41475 collection:collection1 shard:shard2
[junit4:junit4] 2> 1662533 T3974 oasc.ZkController.register We are http://127.0.0.1:41475/collection1/ and leader is http://127.0.0.1:32339/collection1/
[junit4:junit4] 2> 1662534 T3974 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:41475
[junit4:junit4] 2> 1662534 T3974 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1662534 T3974 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1838 name=collection1 org.apache.solr.core.SolrCore@2dcf4de7 url=http://127.0.0.1:41475/collection1 node=127.0.0.1:41475_ C1838_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:41475_, base_url=http://127.0.0.1:41475}
[junit4:junit4] 2> 1662535 T3976 C1838 P41475 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1662535 T3976 C1838 P41475 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1662535 T3974 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1662535 T3976 C1838 P41475 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1662536 T3976 C1838 P41475 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1662536 T3882 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> 1662537 T3882 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1662538 T3882 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1662538 T3976 C1838 P41475 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1662561 T3882 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1662562 T3930 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1662562 T3882 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 1662563 T3882 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 1662563 T3882 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C1839 name=collection1 org.apache.solr.core.SolrCore@2bdf9543 url=http://127.0.0.1:46683/collection1 node=127.0.0.1:46683_ C1839_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:46683_, base_url=http://127.0.0.1:46683}
[junit4:junit4] 2> 1663316 T3959 C1839 P46683 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:51581/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1663316 T3959 C1839 P46683 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:46683 START replicas=[http://127.0.0.1:51581/collection1/] nUpdates=100
[junit4:junit4] 2> 1663317 T3959 C1839 P46683 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1663318 T3959 C1839 P46683 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1663318 T3959 C1839 P46683 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1663318 T3959 C1839 P46683 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1663319 T3959 C1839 P46683 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1663319 T3959 C1839 P46683 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:51581/collection1/. core=collection1
[junit4:junit4] 2> 1663319 T3959 C1839 P46683 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1840 name=collection1 org.apache.solr.core.SolrCore@f90fcb1 url=http://127.0.0.1:51581/collection1 node=127.0.0.1:51581_ C1840_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51581_, base_url=http://127.0.0.1:51581, leader=true}
[junit4:junit4] 2> 1663326 T3915 C1840 P51581 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1663330 T3916 C1840 P51581 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1663334 T3916 C1840 P51581 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232416tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@dec9e19),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1663334 T3916 C1840 P51581 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1663337 T3916 C1840 P51581 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232416tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@dec9e19),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232416tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@dec9e19),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1663337 T3916 C1840 P51581 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1663338 T3916 C1840 P51581 oass.SolrIndexSearcher.<init> Opening Searcher@5375e70f realtime
[junit4:junit4] 2> 1663338 T3916 C1840 P51581 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1663339 T3916 C1840 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 1663340 T3959 C1839 P46683 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1663340 T3959 C1839 P46683 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1663342 T3917 C1840 P51581 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1663343 T3917 C1840 P51581 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 1663343 T3959 C1839 P46683 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1663344 T3959 C1839 P46683 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1663344 T3959 C1839 P46683 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1663346 T3917 C1840 P51581 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> 1663347 T3959 C1839 P46683 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1663348 T3959 C1839 P46683 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty3/index.20130523053747604
[junit4:junit4] 2> 1663349 T3959 C1839 P46683 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@c611c28 lockFactory=org.apache.lucene.store.NativeFSLockFactory@672e5693) fullCopy=false
[junit4:junit4] 2> 1663351 T3917 C1840 P51581 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> 1663353 T3959 C1839 P46683 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1663355 T3959 C1839 P46683 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1663355 T3959 C1839 P46683 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1663359 T3959 C1839 P46683 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232418tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f5bda7),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232418tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f5bda7),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1663359 T3959 C1839 P46683 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1663360 T3959 C1839 P46683 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1663360 T3959 C1839 P46683 oass.SolrIndexSearcher.<init> Opening Searcher@578e6a70 main
[junit4:junit4] 2> 1663361 T3958 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@578e6a70 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1663362 T3959 C1839 P46683 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty3/index.20130523053747604 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty3/index.20130523053747604;done=true>>]
[junit4:junit4] 2> 1663362 T3959 C1839 P46683 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty3/index.20130523053747604
[junit4:junit4] 2> 1663362 T3959 C1839 P46683 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty3/index.20130523053747604
[junit4:junit4] 2> 1663362 T3959 C1839 P46683 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1663363 T3959 C1839 P46683 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1663363 T3959 C1839 P46683 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1663363 T3959 C1839 P46683 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1663365 T3959 C1839 P46683 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1663565 T3882 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1663638 T3905 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1663639 T3905 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:41475_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41475"}
[junit4:junit4] 2> 1663643 T3905 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:46683_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:46683"}
[junit4:junit4] 2> 1663657 T3973 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> 1663657 T3911 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> 1663657 T3956 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> 1663657 T3924 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> 1663657 T3904 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> 1663657 T3940 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> 1664564 T3930 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1664564 T3930 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:41475_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 1664567 T3882 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1665569 T3882 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C1838_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:41475_, base_url=http://127.0.0.1:41475}
[junit4:junit4] 2> 1666566 T3976 C1838 P41475 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:32339/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1666566 T3976 C1838 P41475 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:41475 START replicas=[http://127.0.0.1:32339/collection1/] nUpdates=100
[junit4:junit4] 2> 1666567 T3976 C1838 P41475 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1666567 T3976 C1838 P41475 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1666567 T3976 C1838 P41475 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1666567 T3976 C1838 P41475 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1666568 T3976 C1838 P41475 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1666568 T3976 C1838 P41475 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:32339/collection1/. core=collection1
[junit4:junit4] 2> 1666568 T3976 C1838 P41475 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1666572 T3882 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C1841 name=collection1 org.apache.solr.core.SolrCore@5b3f71df url=http://127.0.0.1:32339/collection1 node=127.0.0.1:32339_ C1841_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:32339_, base_url=http://127.0.0.1:32339, leader=true}
[junit4:junit4] 2> 1666578 T3931 C1841 P32339 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1666585 T3932 C1841 P32339 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1666589 T3932 C1841 P32339 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232417tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@6102a44b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1666590 T3932 C1841 P32339 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1666592 T3932 C1841 P32339 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232417tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@6102a44b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232417tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@6102a44b),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1666592 T3932 C1841 P32339 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1666593 T3932 C1841 P32339 oass.SolrIndexSearcher.<init> Opening Searcher@6f848c2d realtime
[junit4:junit4] 2> 1666594 T3932 C1841 P32339 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1666594 T3932 C1841 P32339 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 10
[junit4:junit4] 2> 1666595 T3976 C1838 P41475 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1666595 T3976 C1838 P41475 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1666597 T3933 C1841 P32339 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1666597 T3933 C1841 P32339 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 1666598 T3976 C1838 P41475 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1666598 T3976 C1838 P41475 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1666598 T3976 C1838 P41475 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1666600 T3933 C1841 P32339 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> 1666601 T3976 C1838 P41475 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1666601 T3976 C1838 P41475 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4/index.20130523053750857
[junit4:junit4] 2> 1666602 T3976 C1838 P41475 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@347e6ee lockFactory=org.apache.lucene.store.NativeFSLockFactory@6db74a2a) fullCopy=false
[junit4:junit4] 2> 1666605 T3933 C1841 P32339 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> 1666607 T3976 C1838 P41475 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1666608 T3976 C1838 P41475 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1666609 T3976 C1838 P41475 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1666612 T3976 C1838 P41475 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232419tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@37f21d44),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232419tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@37f21d44),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1666613 T3976 C1838 P41475 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1666613 T3976 C1838 P41475 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1666613 T3976 C1838 P41475 oass.SolrIndexSearcher.<init> Opening Searcher@5530cf69 main
[junit4:junit4] 2> 1666615 T3975 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5530cf69 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1666615 T3976 C1838 P41475 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4/index.20130523053750857 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4/index.20130523053750857;done=true>>]
[junit4:junit4] 2> 1666616 T3976 C1838 P41475 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4/index.20130523053750857
[junit4:junit4] 2> 1666616 T3976 C1838 P41475 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4/index.20130523053750857
[junit4:junit4] 2> 1666616 T3976 C1838 P41475 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1666616 T3976 C1838 P41475 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1666616 T3976 C1838 P41475 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1666617 T3976 C1838 P41475 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1666618 T3976 C1838 P41475 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1666671 T3905 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1666672 T3905 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:41475_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:41475"}
[junit4:junit4] 2> 1666685 T3904 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> 1666685 T3924 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> 1666685 T3956 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> 1666685 T3911 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> 1666685 T3940 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> 1666685 T3973 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> 1667574 T3882 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1667576 T3882 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C1842 name=collection1 org.apache.solr.core.SolrCore@42d93acf url=http://127.0.0.1:55777/collection1 node=127.0.0.1:55777_ C1842_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:55777_, base_url=http://127.0.0.1:55777, leader=true}
[junit4:junit4] 2> 1667588 T3894 C1842 P55777 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1667592 T3894 C1842 P55777 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232415tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@492631c0),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1667593 T3894 C1842 P55777 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1667595 T3894 C1842 P55777 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232415tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@492631c0),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232415tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@492631c0),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1667595 T3894 C1842 P55777 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1667596 T3894 C1842 P55777 oass.SolrIndexSearcher.<init> Opening Searcher@1f362cfe main
[junit4:junit4] 2> 1667597 T3894 C1842 P55777 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1667598 T3908 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f362cfe main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1667598 T3894 C1842 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 10
[junit4:junit4] 2> 1667611 T3934 C1841 P32339 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1667614 T3934 C1841 P32339 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232417tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@6102a44b),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232417tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@6102a44b),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1667615 T3934 C1841 P32339 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1667615 T3934 C1841 P32339 oass.SolrIndexSearcher.<init> Opening Searcher@616cf82a main
[junit4:junit4] 2> 1667616 T3934 C1841 P32339 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1667617 T3942 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@616cf82a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1667617 T3934 C1841 P32339 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:51581/collection1/, StdNode: http://127.0.0.1:46683/collection1/, StdNode: http://127.0.0.1:41475/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> ASYNC NEW_CORE C1843 name=collection1 org.apache.solr.core.SolrCore@f90fcb1 url=http://127.0.0.1:51581/collection1 node=127.0.0.1:51581_ C1843_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51581_, base_url=http://127.0.0.1:51581, leader=true}
[junit4:junit4] 2> 1667625 T3918 C1843 P51581 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1667630 T3918 C1843 P51581 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232416tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@dec9e19),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232416tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@dec9e19),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1667630 T3918 C1843 P51581 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1667631 T3918 C1843 P51581 oass.SolrIndexSearcher.<init> Opening Searcher@3249bd76 main
[junit4:junit4] 2> 1667631 T3918 C1843 P51581 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1667632 T3926 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3249bd76 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1667633 T3918 C1843 P51581 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 8
[junit4:junit4] 2> ASYNC NEW_CORE C1844 name=collection1 org.apache.solr.core.SolrCore@2dcf4de7 url=http://127.0.0.1:41475/collection1 node=127.0.0.1:41475_ C1844_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:41475_, base_url=http://127.0.0.1:41475}
[junit4:junit4] 2> 1667641 T3963 C1844 P41475 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C1845 name=collection1 org.apache.solr.core.SolrCore@2bdf9543 url=http://127.0.0.1:46683/collection1 node=127.0.0.1:46683_ C1845_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:46683_, base_url=http://127.0.0.1:46683}
[junit4:junit4] 2> 1667641 T3946 C1845 P46683 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1667644 T3963 C1844 P41475 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232419tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@37f21d44),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232419tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@37f21d44),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1667645 T3963 C1844 P41475 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1667645 T3946 C1845 P46683 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232418tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f5bda7),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.MMapDirectory@/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/index3240232418tmp lockFactory=org.apache.lucene.store.NativeFSLockFactory@4f5bda7),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1667646 T3946 C1845 P46683 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1667646 T3963 C1844 P41475 oass.SolrIndexSearcher.<init> Opening Searcher@78b9530a main
[junit4:junit4] 2> 1667646 T3963 C1844 P41475 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1667646 T3946 C1845 P46683 oass.SolrIndexSearcher.<init> Opening Searcher@3d84a839 main
[junit4:junit4] 2> 1667647 T3975 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@78b9530a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1667647 T3946 C1845 P46683 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1667648 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 1667648 T3958 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3d84a839 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1667649 T3946 C1845 P46683 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 8
[junit4:junit4] 2> ASYNC NEW_CORE C1846 name=collection1 org.apache.solr.core.SolrCore@5b3f71df url=http://127.0.0.1:32339/collection1 node=127.0.0.1:32339_ C1846_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:32339_, base_url=http://127.0.0.1:32339, leader=true}
[junit4:junit4] 2> 1667649 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 38
[junit4:junit4] 2> 1667651 T3882 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1667653 T3919 C1843 P51581 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> 1667654 T3947 C1845 P46683 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> 1667656 T3935 C1846 P32339 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> 1667657 T3964 C1844 P41475 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> ASYNC NEW_CORE C1847 name=collection1 org.apache.solr.core.SolrCore@42d93acf url=http://127.0.0.1:55777/collection1 node=127.0.0.1:55777_ C1847_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:55777_, base_url=http://127.0.0.1:55777, leader=true}
[junit4:junit4] 2> 1669663 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435784995318792192)} 0 2
[junit4:junit4] 2> 1669670 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435784995324035072&update.from=http://127.0.0.1:32339/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435784995324035072)} 0 1
[junit4:junit4] 2> 1669674 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435784995327180800&update.from=http://127.0.0.1:51581/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435784995327180800)} 0 1
[junit4:junit4] 2> 1669675 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1435784995327180800)} 0 6
[junit4:junit4] 2> 1669675 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435784995324035072)} 0 9
[junit4:junit4] 2> 1669680 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1435784995336617984)]} 0 2
[junit4:junit4] 2> 1669691 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1435784995343958016)]} 0 2
[junit4:junit4] 2> 1669691 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1435784995343958016)]} 0 6
[junit4:junit4] 2> 1669692 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0]} 0 9
[junit4:junit4] 2> 1669696 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1435784995354443776)]} 0 1
[junit4:junit4] 2> 1669703 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1435784995360735232)]} 0 0
[junit4:junit4] 2> 1669704 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1435784995360735232)]} 0 3
[junit4:junit4] 2> 1669704 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1]} 0 6
[junit4:junit4] 2> 1669707 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1435784995367026688)]} 0 0
[junit4:junit4] 2> 1669717 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1435784995370172416)]} 0 2
[junit4:junit4] 2> 1669717 T3936 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[2 (1435784995370172416)]} 0 7
[junit4:junit4] 2> 1669718 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2]} 0 9
[junit4:junit4] 2> 1669721 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1435784995381706752)]} 0 0
[junit4:junit4] 2> 1669727 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1435784995384852480)]} 0 1
[junit4:junit4] 2> 1669727 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1435784995384852480)]} 0 3
[junit4:junit4] 2> 1669730 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1435784995391143936)]} 0 0
[junit4:junit4] 2> 1669736 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1435784995394289664)]} 0 0
[junit4:junit4] 2> 1669737 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1435784995394289664)]} 0 4
[junit4:junit4] 2> 1669739 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1435784995400581120)]} 0 0
[junit4:junit4] 2> 1669746 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1435784995405824000)]} 0 0
[junit4:junit4] 2> 1669747 T3936 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[5 (1435784995405824000)]} 0 3
[junit4:junit4] 2> 1669748 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5]} 0 6
[junit4:junit4] 2> 1669750 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1435784995412115456)]} 0 0
[junit4:junit4] 2> 1669755 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1435784995415261184)]} 0 0
[junit4:junit4] 2> 1669756 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1435784995415261184)]} 0 3
[junit4:junit4] 2> 1669759 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1435784995421552640)]} 0 1
[junit4:junit4] 2> 1669766 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1435784995426795520)]} 0 0
[junit4:junit4] 2> 1669767 T3936 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[7 (1435784995426795520)]} 0 3
[junit4:junit4] 2> 1669767 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7]} 0 5
[junit4:junit4] 2> 1669770 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1435784995433086976)]} 0 0
[junit4:junit4] 2> 1669777 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1435784995438329856)]} 0 0
[junit4:junit4] 2> 1669778 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1435784995438329856)]} 0 3
[junit4:junit4] 2> 1669778 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8]} 0 5
[junit4:junit4] 2> 1669781 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1435784995444621312)]} 0 0
[junit4:junit4] 2> 1669788 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1435784995449864192)]} 0 0
[junit4:junit4] 2> 1669789 T3936 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[9 (1435784995449864192)]} 0 3
[junit4:junit4] 2> 1669790 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9]} 0 6
[junit4:junit4] 2> 1669792 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1435784995456155648)]} 0 0
[junit4:junit4] 2> 1669799 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1435784995461398528)]} 0 0
[junit4:junit4] 2> 1669800 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[10 (1435784995461398528)]} 0 3
[junit4:junit4] 2> 1669800 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10]} 0 5
[junit4:junit4] 2> 1669803 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1435784995467689984)]} 0 0
[junit4:junit4] 2> 1669810 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1435784995472932864)]} 0 0
[junit4:junit4] 2> 1669811 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[11 (1435784995472932864)]} 0 3
[junit4:junit4] 2> 1669812 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11]} 0 6
[junit4:junit4] 2> 1669814 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1435784995479224320)]} 0 0
[junit4:junit4] 2> 1669819 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1435784995482370048)]} 0 0
[junit4:junit4] 2> 1669820 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1435784995482370048)]} 0 3
[junit4:junit4] 2> 1669822 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1435784995487612928)]} 0 0
[junit4:junit4] 2> 1669827 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1435784995490758656)]} 0 0
[junit4:junit4] 2> 1669828 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1435784995490758656)]} 0 3
[junit4:junit4] 2> 1669830 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1435784995496001536)]} 0 0
[junit4:junit4] 2> 1669837 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1435784995501244416)]} 0 0
[junit4:junit4] 2> 1669838 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[14 (1435784995501244416)]} 0 3
[junit4:junit4] 2> 1669838 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14]} 0 5
[junit4:junit4] 2> 1669841 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1435784995507535872)]} 0 0
[junit4:junit4] 2> 1669848 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1435784995512778752)]} 0 0
[junit4:junit4] 2> 1669849 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[15 (1435784995512778752)]} 0 3
[junit4:junit4] 2> 1669850 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15]} 0 6
[junit4:junit4] 2> 1669852 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1435784995519070208)]} 0 0
[junit4:junit4] 2> 1669859 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1435784995524313088)]} 0 0
[junit4:junit4] 2> 1669860 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[16 (1435784995524313088)]} 0 3
[junit4:junit4] 2> 1669860 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16]} 0 5
[junit4:junit4] 2> 1669863 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1435784995530604544)]} 0 0
[junit4:junit4] 2> 1669868 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1435784995533750272)]} 0 0
[junit4:junit4] 2> 1669869 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1435784995533750272)]} 0 3
[junit4:junit4] 2> 1669872 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1435784995540041728)]} 0 0
[junit4:junit4] 2> 1669879 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1435784995545284608)]} 0 0
[junit4:junit4] 2> 1669880 T3936 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[18 (1435784995545284608)]} 0 3
[junit4:junit4] 2> 1669880 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18]} 0 5
[junit4:junit4] 2> 1669883 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1435784995551576064)]} 0 0
[junit4:junit4] 2> 1669890 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1435784995556818944)]} 0 0
[junit4:junit4] 2> 1669891 T3936 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[19 (1435784995556818944)]} 0 3
[junit4:junit4] 2> 1669891 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19]} 0 5
[junit4:junit4] 2> 1669894 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1435784995563110400)]} 0 0
[junit4:junit4] 2> 1669899 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1435784995566256128)]} 0 0
[junit4:junit4] 2> 1669900 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1435784995566256128)]} 0 3
[junit4:junit4] 2> 1669902 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1435784995571499008)]} 0 0
[junit4:junit4] 2> 1669907 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1435784995574644736)]} 0 0
[junit4:junit4] 2> 1669908 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1435784995574644736)]} 0 3
[junit4:junit4] 2> 1669910 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1435784995579887616)]} 0 0
[junit4:junit4] 2> 1669919 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1435784995585130496)]} 0 1
[junit4:junit4] 2> 1669920 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[22 (1435784995585130496)]} 0 5
[junit4:junit4] 2> 1669920 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22]} 0 7
[junit4:junit4] 2> 1669924 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1435784995594567680)]} 0 1
[junit4:junit4] 2> 1669931 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1435784995599810560)]} 0 0
[junit4:junit4] 2> 1669932 T3936 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[23 (1435784995599810560)]} 0 3
[junit4:junit4] 2> 1669933 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23]} 0 6
[junit4:junit4] 2> 1669935 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1435784995606102016)]} 0 0
[junit4:junit4] 2> 1669940 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1435784995609247744)]} 0 0
[junit4:junit4] 2> 1669941 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1435784995609247744)]} 0 3
[junit4:junit4] 2> 1669943 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1435784995614490624)]} 0 0
[junit4:junit4] 2> 1669948 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1435784995617636352)]} 0 0
[junit4:junit4] 2> 1669949 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1435784995617636352)]} 0 3
[junit4:junit4] 2> 1669951 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1435784995622879232)]} 0 0
[junit4:junit4] 2> 1669956 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1435784995626024960)]} 0 0
[junit4:junit4] 2> 1669957 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1435784995626024960)]} 0 3
[junit4:junit4] 2> 1669960 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1435784995632316416)]} 0 0
[junit4:junit4] 2> 1669966 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1435784995635462144)]} 0 1
[junit4:junit4] 2> 1669967 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1435784995635462144)]} 0 4
[junit4:junit4] 2> 1669970 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1435784995642802176)]} 0 0
[junit4:junit4] 2> 1669978 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1435784995648045056)]} 0 0
[junit4:junit4] 2> 1669979 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[28 (1435784995648045056)]} 0 4
[junit4:junit4] 2> 1669980 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28]} 0 7
[junit4:junit4] 2> 1669982 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1435784995655385088)]} 0 0
[junit4:junit4] 2> 1669989 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1435784995660627968)]} 0 0
[junit4:junit4] 2> 1669990 T3936 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[29 (1435784995660627968)]} 0 3
[junit4:junit4] 2> 1669990 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29]} 0 5
[junit4:junit4] 2> 1669993 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1435784995666919424)]} 0 0
[junit4:junit4] 2> 1670000 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1435784995672162304)]} 0 0
[junit4:junit4] 2> 1670001 T3936 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[30 (1435784995672162304)]} 0 3
[junit4:junit4] 2> 1670001 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30]} 0 5
[junit4:junit4] 2> 1670004 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1435784995678453760)]} 0 0
[junit4:junit4] 2> 1670009 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1435784995681599488)]} 0 0
[junit4:junit4] 2> 1670010 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1435784995681599488)]} 0 3
[junit4:junit4] 2> 1670012 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1435784995686842368)]} 0 0
[junit4:junit4] 2> 1670019 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1435784995692085248)]} 0 0
[junit4:junit4] 2> 1670020 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[32 (1435784995692085248)]} 0 3
[junit4:junit4] 2> 1670021 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32]} 0 5
[junit4:junit4] 2> 1670023 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1435784995698376704)]} 0 0
[junit4:junit4] 2> 1670030 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1435784995703619584)]} 0 0
[junit4:junit4] 2> 1670031 T3936 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[33 (1435784995703619584)]} 0 3
[junit4:junit4] 2> 1670032 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33]} 0 6
[junit4:junit4] 2> 1670034 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1435784995709911040)]} 0 0
[junit4:junit4] 2> 1670039 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1435784995713056768)]} 0 0
[junit4:junit4] 2> 1670040 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1435784995713056768)]} 0 3
[junit4:junit4] 2> 1670042 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1435784995718299648)]} 0 0
[junit4:junit4] 2> 1670047 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1435784995721445376)]} 0 0
[junit4:junit4] 2> 1670048 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1435784995721445376)]} 0 3
[junit4:junit4] 2> 1670050 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1435784995726688256)]} 0 0
[junit4:junit4] 2> 1670057 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1435784995731931136)]} 0 0
[junit4:junit4] 2> 1670058 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[36 (1435784995731931136)]} 0 3
[junit4:junit4] 2> 1670058 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36]} 0 5
[junit4:junit4] 2> 1670061 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1435784995738222592)]} 0 0
[junit4:junit4] 2> 1670066 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1435784995741368320)]} 0 0
[junit4:junit4] 2> 1670067 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1435784995741368320)]} 0 3
[junit4:junit4] 2> 1670069 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1435784995746611200)]} 0 0
[junit4:junit4] 2> 1670074 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1435784995749756928)]} 0 0
[junit4:junit4] 2> 1670075 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1435784995749756928)]} 0 3
[junit4:junit4] 2> 1670077 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1435784995754999808)]} 0 0
[junit4:junit4] 2> 1670082 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1435784995758145536)]} 0 0
[junit4:junit4] 2> 1670083 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1435784995758145536)]} 0 3
[junit4:junit4] 2> 1670085 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1435784995763388416)]} 0 0
[junit4:junit4] 2> 1670090 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1435784995766534144)]} 0 0
[junit4:junit4] 2> 1670091 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1435784995766534144)]} 0 3
[junit4:junit4] 2> 1670093 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1435784995771777024)]} 0 0
[junit4:junit4] 2> 1670098 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1435784995774922752)]} 0 0
[junit4:junit4] 2> 1670099 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1435784995774922752)]} 0 3
[junit4:junit4] 2> 1670101 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1435784995780165632)]} 0 0
[junit4:junit4] 2> 1670106 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1435784995783311360)]} 0 0
[junit4:junit4] 2> 1670107 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1435784995783311360)]} 0 3
[junit4:junit4] 2> 1670109 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1435784995788554240)]} 0 0
[junit4:junit4] 2> 1670116 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1435784995793797120)]} 0 0
[junit4:junit4] 2> 1670117 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[43 (1435784995793797120)]} 0 3
[junit4:junit4] 2> 1670117 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43]} 0 5
[junit4:junit4] 2> 1670120 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1435784995800088576)]} 0 0
[junit4:junit4] 2> 1670127 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1435784995805331456)]} 0 0
[junit4:junit4] 2> 1670128 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[44 (1435784995805331456)]} 0 3
[junit4:junit4] 2> 1670128 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44]} 0 5
[junit4:junit4] 2> 1670131 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1435784995811622912)]} 0 0
[junit4:junit4] 2> 1670138 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1435784995816865792)]} 0 0
[junit4:junit4] 2> 1670139 T3936 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[45 (1435784995816865792)]} 0 3
[junit4:junit4] 2> 1670140 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45]} 0 6
[junit4:junit4] 2> 1670143 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1435784995823157248)]} 0 1
[junit4:junit4] 2> 1670151 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1435784995829448704)]} 0 0
[junit4:junit4] 2> 1670152 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[46 (1435784995829448704)]} 0 4
[junit4:junit4] 2> 1670153 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46]} 0 7
[junit4:junit4] 2> 1670156 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1435784995837837312)]} 0 0
[junit4:junit4] 2> 1670165 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1435784995844128768)]} 0 0
[junit4:junit4] 2> 1670166 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[47 (1435784995844128768)]} 0 4
[junit4:junit4] 2> 1670168 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47]} 0 9
[junit4:junit4] 2> 1670172 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1435784995853565952)]} 0 1
[junit4:junit4] 2> 1670179 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1435784995858808832)]} 0 1
[junit4:junit4] 2> 1670180 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1435784995858808832)]} 0 5
[junit4:junit4] 2> 1670183 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1435784995866148864)]} 0 1
[junit4:junit4] 2> 1670188 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1435784995869294592)]} 0 0
[junit4:junit4] 2> 1670189 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1435784995869294592)]} 0 3
[junit4:junit4] 2> 1670191 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1435784995874537472)]} 0 0
[junit4:junit4] 2> 1670197 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1435784995877683200)]} 0 1
[junit4:junit4] 2> 1670197 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1435784995877683200)]} 0 3
[junit4:junit4] 2> 1670200 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1435784995883974656)]} 0 0
[junit4:junit4] 2> 1670206 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1435784995888168960)]} 0 0
[junit4:junit4] 2> 1670207 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1435784995888168960)]} 0 4
[junit4:junit4] 2> 1670210 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1435784995894460416)]} 0 0
[junit4:junit4] 2> 1670215 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1435784995897606144)]} 0 0
[junit4:junit4] 2> 1670216 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1435784995897606144)]} 0 3
[junit4:junit4] 2> 1670218 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1435784995902849024)]} 0 0
[junit4:junit4] 2> 1670225 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1435784995908091904)]} 0 0
[junit4:junit4] 2> 1670226 T3936 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[53 (1435784995908091904)]} 0 3
[junit4:junit4] 2> 1670227 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53]} 0 6
[junit4:junit4] 2> 1670229 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1435784995914383360)]} 0 0
[junit4:junit4] 2> 1670236 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1435784995919626240)]} 0 0
[junit4:junit4] 2> 1670237 T3918 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[54 (1435784995919626240)]} 0 3
[junit4:junit4] 2> 1670237 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54]} 0 5
[junit4:junit4] 2> 1670240 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1435784995925917696)]} 0 0
[junit4:junit4] 2> 1670245 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1435784995929063424)]} 0 0
[junit4:junit4] 2> 1670246 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1435784995929063424)]} 0 3
[junit4:junit4] 2> 1670248 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1435784995934306304)]} 0 0
[junit4:junit4] 2> 1670253 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1435784995937452032)]} 0 0
[junit4:junit4] 2> 1670254 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1435784995937452032)]} 0 3
[junit4:junit4] 2> 1670256 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1435784995942694912)]} 0 0
[junit4:junit4] 2> 1670263 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1435784995947937792)]} 0 0
[junit4:junit4] 2> 1670264 T3936 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[57 (1435784995947937792)]} 0 3
[junit4:junit4] 2> 1670264 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57]} 0 5
[junit4:junit4] 2> 1670267 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1435784995954229248)]} 0 0
[junit4:junit4] 2> 1670272 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1435784995957374976)]} 0 0
[junit4:junit4] 2> 1670273 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1435784995957374976)]} 0 3
[junit4:junit4] 2> 1670275 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1435784995962617856)]} 0 0
[junit4:junit4] 2> 1670280 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1435784995965763584)]} 0 0
[junit4:junit4] 2> 1670281 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1435784995965763584)]} 0 3
[junit4:junit4] 2> 1670283 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1435784995971006464)]} 0 0
[junit4:junit4] 2> 1670288 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1435784995974152192)]} 0 0
[junit4:junit4] 2> 1670289 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1435784995974152192)]} 0 3
[junit4:junit4] 2> 1670291 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1435784995979395072)]} 0 0
[junit4:junit4] 2> 1670296 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1435784995982540800)]} 0 0
[junit4:junit4] 2> 1670297 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1435784995982540800)]} 0 3
[junit4:junit4] 2> 1670299 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1435784995987783680)]} 0 0
[junit4:junit4] 2> 1670304 T3963 C1844 P41475 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:32339/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[62 (1435784995990929408)]} 0 0
[junit4:junit4] 2> 1670305 T3934 C1846 P32339 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1435784995990929408)]} 0 3
[junit4:junit4] 2> 1670307 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1435784995996172288)]} 0 0
[junit4:junit4] 2> 1670312 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[63 (1435784995999318016)]} 0 0
[junit4:junit4] 2> 1670313 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1435784995999318016)]} 0 3
[junit4:junit4] 2> 1670315 T3894 C1847 P55777 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1435784996004560896)]} 0 0
[junit4:junit4] 2> 1670320 T3948 C1845 P46683 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51581/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[64 (1435784996007706624)]} 0 0
[junit4:junit4] 2> 1670321 T3920 C1843 P51581 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/upd
[...truncated too long message...]
oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 1932005 T3973 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 1932006 T3973 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1932006 T3973 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4;done=false>>]
[junit4:junit4] 2> 1932006 T3973 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4
[junit4:junit4] 2> 1932007 T3973 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4/index;done=false>>]
[junit4:junit4] 2> 1932007 T3973 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369271246717/jetty4/index
[junit4:junit4] 2> 1932007 T3973 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1932007 T3973 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election/89736560425435148-5-n_0000000001
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:152)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:149)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:149)
[junit4:junit4] 2> at org.apache.solr.cloud.ElectionContext.cancelElection(ElectionContext.java:63)
[junit4:junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:260)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:156)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:100)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> 1932008 T3973 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1932008 T3973 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> 1932008 T3973 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1932009 T3973 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> 1932009 T3973 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1932009 T3973 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /overseer_elect/election
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.getChildren(ZooKeeper.java:1468)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:235)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$6.execute(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.getChildren(SolrZkClient.java:232)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:84)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> NOTE: test params are: codec=Asserting, sim=DefaultSimilarity, locale=cs, timezone=Asia/Kabul
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=3,free=299323080,total=492240896
[junit4:junit4] 2> NOTE: All tests run in this JVM: [NotRequiredUniqueKeyTest, TestCollationField, StatsComponentTest, JSONWriterTest, ZkSolrClientTest, TestLMJelinekMercerSimilarityFactory, DirectSolrSpellCheckerTest, CurrencyFieldOpenExchangeTest, FileUtilsTest, BasicZkTest, TestCodecSupport, TestUpdate, TestSolrXMLSerializer, DisMaxRequestHandlerTest, TestCSVLoader, TestDistributedSearch, RequiredFieldsTest, TestLuceneMatchVersion, TestDFRSimilarityFactory, TestAtomicUpdateErrorCases, SuggesterWFSTTest, MultiTermTest, TestMaxScoreQueryParser, TestAddFieldRealTimeGet, TestDistributedGrouping, BadIndexSchemaTest, TestDefaultSimilarityFactory, SpellCheckComponentTest, TestElisionMultitermQuery, TestFiltering, SortByFunctionTest, DocValuesMultiTest, TestNumberUtils, TestCopyFieldCollectionResource, TestSolrJ, PingRequestHandlerTest, CoreContainerCoreInitFailuresTest, TestAnalyzedSuggestions, SolrIndexConfigTest, TestBinaryField, SolrCoreCheckLockOnStartupTest, BasicDistributedZk2Test, NoCacheHeaderTest, ClusterStateTest, CachingDirectoryFactoryTest, DefaultValueUpdateProcessorTest, ZkNodePropsTest, TestJmxMonitoredMap, TestPropInject, TimeZoneUtilsTest, SolrCmdDistributorTest, TestCoreDiscovery, DistanceFunctionTest, TestOmitPositions, CopyFieldTest, CollectionsAPIDistributedZkTest, TestFastOutputStream, TestIndexSearcher, TestDefaultSearchFieldResource, CurrencyFieldXmlFileTest, SpellCheckCollatorTest, TestArbitraryIndexDir, UpdateParamsTest, TestBinaryResponseWriter, IndexBasedSpellCheckerTest, TestLazyCores, TestPostingsSolrHighlighter, DebugComponentTest, TestQuerySenderNoQuery, ChaosMonkeySafeLeaderTest, UnloadDistributedZkTest, OpenCloseCoreStressTest, LeaderElectionIntegrationTest, RecoveryZkTest, FullSolrCloudDistribCmdsTest, LeaderElectionTest, TestZkChroot, TestRandomDVFaceting, AutoCommitTest, TestRecovery, TermVectorComponentDistributedTest, ZkControllerTest, TestMultiCoreConfBootstrap, TestReload, SimpleFacetsTest, TestGroupingSearch, TestBadConfig, SoftAutoCommitTest, SignatureUpdateProcessorFactoryTest, CoreAdminHandlerTest, TestFoldingMultitermQuery, SuggesterTSTTest, SpatialFilterTest, TestPseudoReturnFields, DirectUpdateHandlerOptimizeTest, TestSolrDeletionPolicy1, SolrInfoMBeanTest, StandardRequestHandlerTest, TestWriterPerf, TestQueryTypes, XmlUpdateRequestHandlerTest, TestValueSourceCache, PathHierarchyTokenizerFactoryTest, TestIndexingPerformance, FieldAnalysisRequestHandlerTest, RegexBoostProcessorTest, TestJmxIntegration, TestCSVResponseWriter, QueryParsingTest, JsonLoaderTest, TestPartialUpdateDeduplication, TestComponentsName, TestPropInjectDefaults, TestSolrIndexConfig, TestMergePolicyConfig, TestSolrDeletionPolicy2, NumericFieldsTest, OutputWriterTest, SpellPossibilityIteratorTest, EchoParamsTest, TestIBSimilarityFactory, LegacyHTMLStripCharFilterTest, ScriptEngineTest, URLClassifyProcessorTest, DateMathParserTest, TestSystemIdResolver, PrimUtilsTest, TestSuggestSpellingConverter, DOMUtilTest, TestUtils, SystemInfoHandlerTest, UUIDFieldTest, SolrTestCaseJ4Test, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J1 in 290.04s, 1 test, 1 error <<< FAILURES!
[...truncated 10 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:386: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:366: 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 error, 13 ignored (7 assumptions)
Total time: 52 minutes 33 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure