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/29 20:52:17 UTC
[JENKINS] Lucene-Solr-Tests-trunk-Java7 - Build # 4026 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-trunk-Java7/4026/
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:29887 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:29887 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([545C77422A5EB1DE:D5BAF95A5D01D1E2]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 10109 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 1724013 T3805 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 1724020 T3805 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./solrtest-ChaosMonkeyShardSplitTest-1369853234262
[junit4:junit4] 2> 1724022 T3805 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1724022 T3806 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1724123 T3805 oasc.ZkTestServer.run start zk server on port:48891
[junit4:junit4] 2> 1724124 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1724130 T3812 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3a96c9ca name:ZooKeeperConnection Watcher:127.0.0.1:48891 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1724131 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1724132 T3805 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1724152 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1724155 T3814 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@47b8079f name:ZooKeeperConnection Watcher:127.0.0.1:48891/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1724155 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1724156 T3805 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1724165 T3805 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1724169 T3805 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1724171 T3805 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1724180 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1724180 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1724194 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 1724195 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1724200 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1724200 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1724204 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 1724205 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1724213 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 1724214 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1724217 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1724218 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1724221 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1724222 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1724225 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1724226 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1724230 T3805 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1724231 T3805 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1724541 T3805 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1724548 T3805 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:49448
[junit4:junit4] 2> 1724549 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1724549 T3805 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1724550 T3805 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369853234476
[junit4:junit4] 2> 1724551 T3805 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369853234476/solr.xml
[junit4:junit4] 2> 1724551 T3805 oasc.CoreContainer.<init> New CoreContainer 766971190
[junit4:junit4] 2> 1724552 T3805 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369853234476/'
[junit4:junit4] 2> 1724553 T3805 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369853234476/'
[junit4:junit4] 2> 1724722 T3805 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1724723 T3805 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1724724 T3805 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1724725 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1724725 T3805 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1724726 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1724726 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1724727 T3805 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1724727 T3805 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1724728 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1724754 T3805 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1724756 T3805 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:48891/solr
[junit4:junit4] 2> 1724756 T3805 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1724757 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1724760 T3825 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4a58864f name:ZooKeeperConnection Watcher:127.0.0.1:48891 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1724761 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1724763 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1724778 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1724780 T3827 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@47d3328c name:ZooKeeperConnection Watcher:127.0.0.1:48891/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1724780 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1724783 T3805 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1724792 T3805 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1724797 T3805 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1724799 T3805 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:49448_
[junit4:junit4] 2> 1724806 T3805 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:49448_
[junit4:junit4] 2> 1724810 T3805 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1724828 T3805 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1724832 T3805 oasc.Overseer.start Overseer (id=89774701561184259-127.0.0.1:49448_-n_0000000000) starting
[junit4:junit4] 2> 1724845 T3805 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1724856 T3829 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1724857 T3805 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1724866 T3805 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1724878 T3805 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1724881 T3828 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1724885 T3830 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369853234476/collection1
[junit4:junit4] 2> 1724886 T3830 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1724887 T3830 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1724887 T3830 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1724889 T3830 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369853234476/collection1/'
[junit4:junit4] 2> 1724890 T3830 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369853234476/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1724891 T3830 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369853234476/collection1/lib/README' to classloader
[junit4:junit4] 2> 1724951 T3830 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1725017 T3830 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1725019 T3830 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1725027 T3830 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1725659 T3830 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1725663 T3830 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1725665 T3830 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1725671 T3830 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1725694 T3830 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1725695 T3830 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369853234476/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/control/data/
[junit4:junit4] 2> 1725696 T3830 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5d1a4ce8
[junit4:junit4] 2> 1725696 T3830 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1725697 T3830 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/control/data
[junit4:junit4] 2> 1725697 T3830 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/control/data/index/
[junit4:junit4] 2> 1725698 T3830 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1725698 T3830 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/control/data/index
[junit4:junit4] 2> 1725704 T3830 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@70793c95 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ef7c8f3),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1725705 T3830 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1725709 T3830 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1725709 T3830 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1725710 T3830 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1725711 T3830 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1725711 T3830 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1725712 T3830 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1725712 T3830 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1725713 T3830 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1725713 T3830 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1725738 T3830 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1725750 T3830 oass.SolrIndexSearcher.<init> Opening Searcher@4438f89b main
[junit4:junit4] 2> 1725751 T3830 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/control/data/tlog
[junit4:junit4] 2> 1725753 T3830 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1725753 T3830 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1725758 T3831 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4438f89b main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1725760 T3830 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1725760 T3830 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1726384 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1726385 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49448_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49448"}
[junit4:junit4] 2> 1726386 T3828 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1726386 T3828 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1726400 T3827 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> 1726764 T3830 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1726764 T3830 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:49448 collection:control_collection shard:shard1
[junit4:junit4] 2> 1726765 T3830 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1726784 T3830 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1726793 T3830 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1726794 T3830 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1726794 T3830 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:49448/collection1/
[junit4:junit4] 2> 1726794 T3830 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1726795 T3830 oasc.SyncStrategy.syncToMe http://127.0.0.1:49448/collection1/ has no replicas
[junit4:junit4] 2> 1726795 T3830 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:49448/collection1/
[junit4:junit4] 2> 1726795 T3830 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1727905 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1727928 T3827 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> 1727986 T3830 oasc.ZkController.register We are http://127.0.0.1:49448/collection1/ and leader is http://127.0.0.1:49448/collection1/
[junit4:junit4] 2> 1727986 T3830 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:49448
[junit4:junit4] 2> 1727987 T3830 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1727987 T3830 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1727987 T3830 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1727993 T3830 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1727994 T3805 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1727995 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1727996 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1728042 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1728044 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1728049 T3834 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@24ff4867 name:ZooKeeperConnection Watcher:127.0.0.1:48891/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1728050 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1728051 T3805 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1728054 T3805 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1728396 T3805 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1728399 T3805 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:29887
[junit4:junit4] 2> 1728399 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1728400 T3805 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1728401 T3805 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369853238295
[junit4:junit4] 2> 1728401 T3805 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369853238295/solr.xml
[junit4:junit4] 2> 1728402 T3805 oasc.CoreContainer.<init> New CoreContainer 576767071
[junit4:junit4] 2> 1728403 T3805 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369853238295/'
[junit4:junit4] 2> 1728403 T3805 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369853238295/'
[junit4:junit4] 2> 1728553 T3805 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1728554 T3805 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1728555 T3805 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1728555 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1728556 T3805 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1728556 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1728557 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1728558 T3805 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1728558 T3805 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1728559 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1728578 T3805 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1728580 T3805 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:48891/solr
[junit4:junit4] 2> 1728580 T3805 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1728581 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1728611 T3845 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6867f8e6 name:ZooKeeperConnection Watcher:127.0.0.1:48891 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1728611 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1728626 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1728643 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1728652 T3847 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4617e74d name:ZooKeeperConnection Watcher:127.0.0.1:48891/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1728653 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1728665 T3805 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1729443 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1729444 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:49448__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:49448_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:49448"}
[junit4:junit4] 2> 1729483 T3834 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> 1729483 T3847 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> 1729483 T3827 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> 1729670 T3805 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:29887_
[junit4:junit4] 2> 1729673 T3805 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:29887_
[junit4:junit4] 2> 1729675 T3827 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 1729676 T3834 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1729676 T3847 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1729676 T3834 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> 1729676 T3847 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> 1729677 T3827 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1729693 T3848 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369853238295/collection1
[junit4:junit4] 2> 1729694 T3848 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1729695 T3848 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1729695 T3848 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1729697 T3848 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369853238295/collection1/'
[junit4:junit4] 2> 1729698 T3848 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369853238295/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1729699 T3848 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369853238295/collection1/lib/README' to classloader
[junit4:junit4] 2> 1729756 T3848 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1729825 T3848 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1729827 T3848 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1729835 T3848 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1730433 T3848 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1730438 T3848 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1730440 T3848 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1730446 T3848 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1730472 T3848 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1730473 T3848 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369853238295/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty1/
[junit4:junit4] 2> 1730473 T3848 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5d1a4ce8
[junit4:junit4] 2> 1730474 T3848 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1730474 T3848 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty1
[junit4:junit4] 2> 1730475 T3848 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty1/index/
[junit4:junit4] 2> 1730475 T3848 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1730477 T3848 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty1/index
[junit4:junit4] 2> 1730482 T3848 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@433c9c9d lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ea32dfe),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1730483 T3848 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1730487 T3848 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1730487 T3848 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1730488 T3848 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1730489 T3848 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1730490 T3848 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1730490 T3848 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1730490 T3848 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1730491 T3848 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1730492 T3848 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1730510 T3848 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1730519 T3848 oass.SolrIndexSearcher.<init> Opening Searcher@2420b010 main
[junit4:junit4] 2> 1730519 T3848 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty1/tlog
[junit4:junit4] 2> 1730521 T3848 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1730521 T3848 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1730527 T3849 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2420b010 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1730530 T3848 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1730531 T3848 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1730988 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1730989 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:29887_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:29887"}
[junit4:junit4] 2> 1730989 T3828 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 1730989 T3828 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1731007 T3834 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> 1731008 T3847 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> 1731007 T3827 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> 1731559 T3848 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1731559 T3848 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:29887 collection:collection1 shard:shard1
[junit4:junit4] 2> 1731560 T3848 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 1731587 T3848 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1731591 T3848 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1731591 T3848 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1731591 T3848 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:29887/collection1/
[junit4:junit4] 2> 1731592 T3848 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1731592 T3848 oasc.SyncStrategy.syncToMe http://127.0.0.1:29887/collection1/ has no replicas
[junit4:junit4] 2> 1731592 T3848 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:29887/collection1/
[junit4:junit4] 2> 1731593 T3848 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1732513 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1732603 T3847 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> 1732603 T3834 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> 1732603 T3827 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> 1732638 T3848 oasc.ZkController.register We are http://127.0.0.1:29887/collection1/ and leader is http://127.0.0.1:29887/collection1/
[junit4:junit4] 2> 1732638 T3848 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:29887
[junit4:junit4] 2> 1732639 T3848 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1732639 T3848 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1732639 T3848 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1732641 T3848 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1732643 T3805 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1732644 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1732645 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1732964 T3805 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1732968 T3805 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:51222
[junit4:junit4] 2> 1732968 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1732969 T3805 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1732970 T3805 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369853242904
[junit4:junit4] 2> 1732970 T3805 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369853242904/solr.xml
[junit4:junit4] 2> 1732971 T3805 oasc.CoreContainer.<init> New CoreContainer 123302237
[junit4:junit4] 2> 1732972 T3805 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369853242904/'
[junit4:junit4] 2> 1732973 T3805 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369853242904/'
[junit4:junit4] 2> 1733121 T3805 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1733122 T3805 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1733123 T3805 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1733123 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1733124 T3805 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1733124 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1733125 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1733125 T3805 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1733126 T3805 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1733127 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1733148 T3805 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1733150 T3805 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:48891/solr
[junit4:junit4] 2> 1733150 T3805 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1733151 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1733157 T3861 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@17db45f6 name:ZooKeeperConnection Watcher:127.0.0.1:48891 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1733158 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1733175 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1733188 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1733191 T3863 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5bf04fc7 name:ZooKeeperConnection Watcher:127.0.0.1:48891/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1733191 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1733203 T3805 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1734111 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1734112 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:29887__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:29887_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:29887"}
[junit4:junit4] 2> 1734131 T3847 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> 1734131 T3863 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> 1734131 T3827 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> 1734131 T3834 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> 1734207 T3805 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:51222_
[junit4:junit4] 2> 1734210 T3805 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:51222_
[junit4:junit4] 2> 1734212 T3827 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> 1734212 T3863 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> 1734213 T3847 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1734213 T3834 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1734213 T3847 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> 1734213 T3834 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> 1734214 T3827 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1734221 T3863 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1734228 T3864 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369853242904/collection1
[junit4:junit4] 2> 1734228 T3864 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1734229 T3864 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1734230 T3864 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1734231 T3864 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369853242904/collection1/'
[junit4:junit4] 2> 1734233 T3864 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369853242904/collection1/lib/README' to classloader
[junit4:junit4] 2> 1734233 T3864 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369853242904/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1734290 T3864 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1734356 T3864 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1734358 T3864 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1734366 T3864 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1735027 T3864 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1735031 T3864 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1735033 T3864 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1735038 T3864 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1735058 T3864 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1735059 T3864 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369853242904/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty2/
[junit4:junit4] 2> 1735059 T3864 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5d1a4ce8
[junit4:junit4] 2> 1735059 T3864 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1735062 T3864 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty2
[junit4:junit4] 2> 1735062 T3864 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty2/index/
[junit4:junit4] 2> 1735062 T3864 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1735063 T3864 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty2/index
[junit4:junit4] 2> 1735067 T3864 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@639773b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@be37cd2),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1735067 T3864 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1735070 T3864 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1735071 T3864 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1735071 T3864 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1735072 T3864 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1735072 T3864 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1735072 T3864 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1735073 T3864 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1735073 T3864 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1735074 T3864 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1735094 T3864 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1735103 T3864 oass.SolrIndexSearcher.<init> Opening Searcher@18859b61 main
[junit4:junit4] 2> 1735103 T3864 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty2/tlog
[junit4:junit4] 2> 1735105 T3864 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1735105 T3864 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1735109 T3865 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@18859b61 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1735111 T3864 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1735111 T3864 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1735636 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1735637 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51222_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51222"}
[junit4:junit4] 2> 1735637 T3828 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1735637 T3828 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1735651 T3834 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> 1735651 T3827 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> 1735651 T3847 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> 1735651 T3863 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> 1736114 T3864 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1736114 T3864 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:51222 collection:collection1 shard:shard2
[junit4:junit4] 2> 1736115 T3864 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 1736132 T3864 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1736141 T3864 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1736141 T3864 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1736141 T3864 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:51222/collection1/
[junit4:junit4] 2> 1736142 T3864 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1736142 T3864 oasc.SyncStrategy.syncToMe http://127.0.0.1:51222/collection1/ has no replicas
[junit4:junit4] 2> 1736142 T3864 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:51222/collection1/
[junit4:junit4] 2> 1736142 T3864 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1737156 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1737257 T3863 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> 1737257 T3834 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> 1737257 T3847 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> 1737257 T3827 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> 1737279 T3864 oasc.ZkController.register We are http://127.0.0.1:51222/collection1/ and leader is http://127.0.0.1:51222/collection1/
[junit4:junit4] 2> 1737279 T3864 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:51222
[junit4:junit4] 2> 1737280 T3864 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1737280 T3864 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1737280 T3864 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1737327 T3864 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1737329 T3805 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1737330 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1737330 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1737642 T3805 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1737645 T3805 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:58107
[junit4:junit4] 2> 1737646 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1737646 T3805 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1737647 T3805 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369853247589
[junit4:junit4] 2> 1737647 T3805 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369853247589/solr.xml
[junit4:junit4] 2> 1737648 T3805 oasc.CoreContainer.<init> New CoreContainer 1155702280
[junit4:junit4] 2> 1737649 T3805 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369853247589/'
[junit4:junit4] 2> 1737650 T3805 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369853247589/'
[junit4:junit4] 2> 1737793 T3805 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1737794 T3805 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1737795 T3805 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1737795 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1737796 T3805 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1737796 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1737797 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1737797 T3805 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1737798 T3805 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1737799 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1737818 T3805 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1737819 T3805 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:48891/solr
[junit4:junit4] 2> 1737820 T3805 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1737821 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1737828 T3877 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2d135262 name:ZooKeeperConnection Watcher:127.0.0.1:48891 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1737828 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1737849 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1737862 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1737865 T3879 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5b030856 name:ZooKeeperConnection Watcher:127.0.0.1:48891/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1737865 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1737877 T3805 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1738814 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1738815 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:51222__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:51222_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:51222"}
[junit4:junit4] 2> 1738860 T3863 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> 1738860 T3834 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> 1738860 T3827 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> 1738860 T3879 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> 1738860 T3847 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> 1738882 T3805 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:58107_
[junit4:junit4] 2> 1738885 T3805 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:58107_
[junit4:junit4] 2> 1738887 T3827 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> 1738888 T3879 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1738888 T3834 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1738888 T3847 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1738887 T3863 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> 1738889 T3847 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> 1738888 T3834 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> 1738888 T3879 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> 1738895 T3827 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1738896 T3863 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1738903 T3880 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369853247589/collection1
[junit4:junit4] 2> 1738903 T3880 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1738904 T3880 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1738904 T3880 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1738906 T3880 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369853247589/collection1/'
[junit4:junit4] 2> 1738908 T3880 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369853247589/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1738908 T3880 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369853247589/collection1/lib/README' to classloader
[junit4:junit4] 2> 1738974 T3880 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1739043 T3880 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1739045 T3880 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1739052 T3880 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1739722 T3880 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1739726 T3880 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1739729 T3880 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1739734 T3880 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1739758 T3880 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1739758 T3880 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369853247589/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty3/
[junit4:junit4] 2> 1739759 T3880 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5d1a4ce8
[junit4:junit4] 2> 1739759 T3880 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1739760 T3880 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty3
[junit4:junit4] 2> 1739760 T3880 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty3/index/
[junit4:junit4] 2> 1739761 T3880 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1739762 T3880 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty3/index
[junit4:junit4] 2> 1739766 T3880 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@43bf1e8b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e13d574),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1739766 T3880 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1739770 T3880 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1739770 T3880 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1739771 T3880 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1739772 T3880 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1739773 T3880 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1739773 T3880 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1739773 T3880 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1739774 T3880 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1739775 T3880 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1739792 T3880 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1739800 T3880 oass.SolrIndexSearcher.<init> Opening Searcher@80ce95a main
[junit4:junit4] 2> 1739801 T3880 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty3/tlog
[junit4:junit4] 2> 1739802 T3880 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1739803 T3880 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1739807 T3881 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@80ce95a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1739810 T3880 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1739810 T3880 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1740365 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1740366 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:58107_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58107"}
[junit4:junit4] 2> 1740367 T3828 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1740367 T3828 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1740391 T3847 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> 1740391 T3879 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> 1740391 T3834 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> 1740391 T3827 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> 1740391 T3863 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> 1740814 T3880 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1740814 T3880 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:58107 collection:collection1 shard:shard1
[junit4:junit4] 2> 1740818 T3880 oasc.ZkController.register We are http://127.0.0.1:58107/collection1/ and leader is http://127.0.0.1:29887/collection1/
[junit4:junit4] 2> 1740818 T3880 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:58107
[junit4:junit4] 2> 1740819 T3880 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1740819 T3880 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C629 name=collection1 org.apache.solr.core.SolrCore@c118f02 url=http://127.0.0.1:58107/collection1 node=127.0.0.1:58107_ C629_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:58107_, base_url=http://127.0.0.1:58107}
[junit4:junit4] 2> 1740819 T3882 C629 P58107 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1740820 T3880 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1740821 T3882 C629 P58107 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1740822 T3882 C629 P58107 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1740822 T3882 C629 P58107 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1740823 T3805 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1740824 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1740824 T3882 C629 P58107 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1740824 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1740847 T3837 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:58107__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1741141 T3805 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1741144 T3805 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:19314
[junit4:junit4] 2> 1741145 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1741146 T3805 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1741146 T3805 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369853251086
[junit4:junit4] 2> 1741147 T3805 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369853251086/solr.xml
[junit4:junit4] 2> 1741147 T3805 oasc.CoreContainer.<init> New CoreContainer 1710536193
[junit4:junit4] 2> 1741148 T3805 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369853251086/'
[junit4:junit4] 2> 1741149 T3805 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369853251086/'
[junit4:junit4] 2> 1741303 T3805 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1741304 T3805 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1741305 T3805 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1741305 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1741306 T3805 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1741306 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1741307 T3805 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1741307 T3805 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1741308 T3805 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1741309 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1741329 T3805 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1741330 T3805 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:48891/solr
[junit4:junit4] 2> 1741331 T3805 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1741332 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1741335 T3894 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@428f26d8 name:ZooKeeperConnection Watcher:127.0.0.1:48891 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1741335 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1741347 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1741360 T3805 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1741362 T3896 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4a406ebb name:ZooKeeperConnection Watcher:127.0.0.1:48891/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1741363 T3805 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1741374 T3805 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1741898 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1741899 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58107__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:58107_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58107"}
[junit4:junit4] 2> 1741913 T3879 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> 1741913 T3863 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> 1741913 T3827 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> 1741913 T3847 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> 1741913 T3834 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> 1741913 T3896 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> 1742378 T3805 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:19314_
[junit4:junit4] 2> 1742381 T3805 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:19314_
[junit4:junit4] 2> 1742383 T3896 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> 1742384 T3879 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1742384 T3847 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1742383 T3827 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> 1742383 T3863 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> 1742384 T3847 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> 1742385 T3896 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1742384 T3879 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> 1742384 T3834 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1742386 T3834 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> 1742428 T3827 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1742429 T3863 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1742435 T3897 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369853251086/collection1
[junit4:junit4] 2> 1742436 T3897 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1742437 T3897 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1742437 T3897 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1742439 T3897 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369853251086/collection1/'
[junit4:junit4] 2> 1742440 T3897 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369853251086/collection1/lib/README' to classloader
[junit4:junit4] 2> 1742441 T3897 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369853251086/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1742506 T3897 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1742572 T3897 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1742574 T3897 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1742580 T3897 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1742850 T3837 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:58107__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1742850 T3837 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:58107__collection1&state=recovering&nodeName=127.0.0.1:58107_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 1743217 T3897 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1743221 T3897 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1743224 T3897 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1743229 T3897 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1743254 T3897 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1743255 T3897 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369853251086/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4/
[junit4:junit4] 2> 1743255 T3897 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@5d1a4ce8
[junit4:junit4] 2> 1743256 T3897 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1743257 T3897 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4
[junit4:junit4] 2> 1743257 T3897 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4/index/
[junit4:junit4] 2> 1743257 T3897 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1743259 T3897 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4/index
[junit4:junit4] 2> 1743263 T3897 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e4480e6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@29f49a72),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1743263 T3897 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1743267 T3897 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1743267 T3897 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1743268 T3897 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1743269 T3897 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1743270 T3897 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1743270 T3897 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1743271 T3897 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1743271 T3897 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1743272 T3897 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1743292 T3897 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1743300 T3897 oass.SolrIndexSearcher.<init> Opening Searcher@28d5cedc main
[junit4:junit4] 2> 1743301 T3897 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4/tlog
[junit4:junit4] 2> 1743302 T3897 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1743302 T3897 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1743307 T3898 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@28d5cedc main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1743310 T3897 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1743310 T3897 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1743418 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1743420 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:19314_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19314"}
[junit4:junit4] 2> 1743420 T3828 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1743420 T3828 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1743433 T3896 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> 1743434 T3863 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> 1743433 T3834 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> 1743433 T3827 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> 1743433 T3879 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> 1743433 T3847 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> 1744325 T3897 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1744325 T3897 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:19314 collection:collection1 shard:shard2
[junit4:junit4] 2> 1744329 T3897 oasc.ZkController.register We are http://127.0.0.1:19314/collection1/ and leader is http://127.0.0.1:51222/collection1/
[junit4:junit4] 2> 1744329 T3897 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:19314
[junit4:junit4] 2> 1744330 T3897 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1744330 T3897 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C630 name=collection1 org.apache.solr.core.SolrCore@683da4ca url=http://127.0.0.1:19314/collection1 node=127.0.0.1:19314_ C630_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:19314_, base_url=http://127.0.0.1:19314}
[junit4:junit4] 2> 1744330 T3899 C630 P19314 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1744331 T3897 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1744333 T3899 C630 P19314 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1744333 T3899 C630 P19314 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1744333 T3899 C630 P19314 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1744334 T3805 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1744335 T3805 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1744335 T3899 C630 P19314 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1744335 T3805 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1744362 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1744362 T3853 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:19314__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1744363 T3805 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 1744364 T3805 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 1744365 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C629_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:58107_, base_url=http://127.0.0.1:58107}
[junit4:junit4] 2> 1744852 T3882 C629 P58107 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:29887/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1744852 T3882 C629 P58107 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:58107 START replicas=[http://127.0.0.1:29887/collection1/] nUpdates=100
[junit4:junit4] 2> 1744853 T3882 C629 P58107 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1744855 T3882 C629 P58107 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1744855 T3882 C629 P58107 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1744855 T3882 C629 P58107 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1744856 T3882 C629 P58107 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1744856 T3882 C629 P58107 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:29887/collection1/. core=collection1
[junit4:junit4] 2> 1744856 T3882 C629 P58107 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C631 name=collection1 org.apache.solr.core.SolrCore@47f336d8 url=http://127.0.0.1:29887/collection1 node=127.0.0.1:29887_ C631_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:29887_, base_url=http://127.0.0.1:29887, leader=true}
[junit4:junit4] 2> 1744864 T3838 C631 P29887 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 1744870 T3839 C631 P29887 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1744874 T3839 C631 P29887 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@433c9c9d lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ea32dfe),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1744875 T3839 C631 P29887 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1744875 T3839 C631 P29887 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@433c9c9d lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ea32dfe),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@433c9c9d lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ea32dfe),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1744876 T3839 C631 P29887 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1744877 T3839 C631 P29887 oass.SolrIndexSearcher.<init> Opening Searcher@5789a734 realtime
[junit4:junit4] 2> 1744877 T3839 C631 P29887 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1744878 T3839 C631 P29887 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 8
[junit4:junit4] 2> 1744879 T3882 C629 P58107 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1744879 T3882 C629 P58107 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1744882 T3840 C631 P29887 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1744882 T3840 C631 P29887 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 1744883 T3882 C629 P58107 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1744884 T3882 C629 P58107 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1744884 T3882 C629 P58107 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1744886 T3840 C631 P29887 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> 1744887 T3882 C629 P58107 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1744889 T3882 C629 P58107 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty3/index.20130530044735129
[junit4:junit4] 2> 1744889 T3882 C629 P58107 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@188c1a99 lockFactory=org.apache.lucene.store.NativeFSLockFactory@668ca517) fullCopy=false
[junit4:junit4] 2> 1744893 T3840 C631 P29887 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> 1744895 T3882 C629 P58107 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1744896 T3882 C629 P58107 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1744896 T3882 C629 P58107 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1744898 T3882 C629 P58107 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@43bf1e8b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e13d574),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@43bf1e8b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e13d574),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1744899 T3882 C629 P58107 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1744899 T3882 C629 P58107 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1744900 T3882 C629 P58107 oass.SolrIndexSearcher.<init> Opening Searcher@5ea4074b main
[junit4:junit4] 2> 1744901 T3881 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5ea4074b main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1744902 T3882 C629 P58107 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty3/index.20130530044735129 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty3/index.20130530044735129;done=true>>]
[junit4:junit4] 2> 1744902 T3882 C629 P58107 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty3/index.20130530044735129
[junit4:junit4] 2> 1744902 T3882 C629 P58107 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty3/index.20130530044735129
[junit4:junit4] 2> 1744903 T3882 C629 P58107 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1744903 T3882 C629 P58107 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1744903 T3882 C629 P58107 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1744903 T3882 C629 P58107 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1744905 T3882 C629 P58107 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1744938 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1744940 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:19314__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:19314_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19314"}
[junit4:junit4] 2> 1744944 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:58107__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:58107_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:58107"}
[junit4:junit4] 2> 1744957 T3879 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> 1744958 T3896 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> 1744957 T3863 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> 1744957 T3847 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> 1744957 T3834 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> 1744957 T3827 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> 1745365 T3853 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:19314__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 1745365 T3853 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:19314__collection1&state=recovering&nodeName=127.0.0.1:19314_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1003
[junit4:junit4] 2> 1745367 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1746370 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C630_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:19314_, base_url=http://127.0.0.1:19314}
[junit4:junit4] 2> 1747367 T3899 C630 P19314 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:51222/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1747367 T3899 C630 P19314 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:19314 START replicas=[http://127.0.0.1:51222/collection1/] nUpdates=100
[junit4:junit4] 2> 1747368 T3899 C630 P19314 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1747368 T3899 C630 P19314 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1747368 T3899 C630 P19314 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1747369 T3899 C630 P19314 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1747369 T3899 C630 P19314 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1747369 T3899 C630 P19314 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:51222/collection1/. core=collection1
[junit4:junit4] 2> 1747370 T3899 C630 P19314 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1747373 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C632 name=collection1 org.apache.solr.core.SolrCore@2231cb57 url=http://127.0.0.1:51222/collection1 node=127.0.0.1:51222_ C632_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:51222_, base_url=http://127.0.0.1:51222, leader=true}
[junit4:junit4] 2> 1747379 T3854 C632 P51222 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 1747383 T3855 C632 P51222 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1747387 T3855 C632 P51222 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@639773b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@be37cd2),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1747388 T3855 C632 P51222 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1747389 T3855 C632 P51222 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@639773b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@be37cd2),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@639773b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@be37cd2),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1747389 T3855 C632 P51222 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1747390 T3855 C632 P51222 oass.SolrIndexSearcher.<init> Opening Searcher@38bfad76 realtime
[junit4:junit4] 2> 1747391 T3855 C632 P51222 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1747392 T3855 C632 P51222 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> 1747393 T3899 C630 P19314 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1747394 T3899 C630 P19314 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1747397 T3856 C632 P51222 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1747398 T3856 C632 P51222 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 1747399 T3899 C630 P19314 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1747399 T3899 C630 P19314 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1747399 T3899 C630 P19314 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1747402 T3856 C632 P51222 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> 1747403 T3899 C630 P19314 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1747405 T3899 C630 P19314 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4/index.20130530044737645
[junit4:junit4] 2> 1747405 T3899 C630 P19314 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@5deb4282 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3effef40) fullCopy=false
[junit4:junit4] 2> 1747409 T3856 C632 P51222 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> 1747411 T3899 C630 P19314 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1747412 T3899 C630 P19314 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1747412 T3899 C630 P19314 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1747414 T3899 C630 P19314 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e4480e6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@29f49a72),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e4480e6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@29f49a72),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1747414 T3899 C630 P19314 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1747415 T3899 C630 P19314 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1747415 T3899 C630 P19314 oass.SolrIndexSearcher.<init> Opening Searcher@ca8a25 main
[junit4:junit4] 2> 1747416 T3898 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@ca8a25 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1747417 T3899 C630 P19314 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4/index.20130530044737645 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4/index.20130530044737645;done=true>>]
[junit4:junit4] 2> 1747417 T3899 C630 P19314 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4/index.20130530044737645
[junit4:junit4] 2> 1747418 T3899 C630 P19314 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4/index.20130530044737645
[junit4:junit4] 2> 1747418 T3899 C630 P19314 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1747418 T3899 C630 P19314 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1747418 T3899 C630 P19314 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1747419 T3899 C630 P19314 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1747421 T3899 C630 P19314 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1747974 T3828 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1747976 T3828 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:19314__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:19314_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:19314"}
[junit4:junit4] 2> 1748024 T3827 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> 1748024 T3863 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> 1748024 T3896 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> 1748024 T3879 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> 1748024 T3834 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> 1748024 T3847 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> 1748376 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1748378 T3805 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C633 name=collection1 org.apache.solr.core.SolrCore@787dbc42 url=http://127.0.0.1:49448/collection1 node=127.0.0.1:49448_ C633_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:49448_, base_url=http://127.0.0.1:49448, leader=true}
[junit4:junit4] 2> 1748387 T3817 C633 P49448 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1748394 T3817 C633 P49448 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@70793c95 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ef7c8f3),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1748396 T3817 C633 P49448 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1748397 T3817 C633 P49448 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@70793c95 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ef7c8f3),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@70793c95 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4ef7c8f3),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1748398 T3817 C633 P49448 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1748399 T3817 C633 P49448 oass.SolrIndexSearcher.<init> Opening Searcher@2e9373e8 main
[junit4:junit4] 2> 1748399 T3817 C633 P49448 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1748400 T3831 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2e9373e8 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1748401 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 14
[junit4:junit4] 2> 1748414 T3841 C631 P29887 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1748415 T3841 C631 P29887 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@433c9c9d lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ea32dfe),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@433c9c9d lockFactory=org.apache.lucene.store.NativeFSLockFactory@3ea32dfe),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1748416 T3841 C631 P29887 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1748416 T3841 C631 P29887 oass.SolrIndexSearcher.<init> Opening Searcher@1588dd20 main
[junit4:junit4] 2> 1748417 T3841 C631 P29887 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1748418 T3849 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1588dd20 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1748418 T3841 C631 P29887 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:58107/collection1/, StdNode: http://127.0.0.1:51222/collection1/, StdNode: http://127.0.0.1:19314/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 1748422 T3857 C632 P51222 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1748423 T3857 C632 P51222 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@639773b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@be37cd2),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@639773b1 lockFactory=org.apache.lucene.store.NativeFSLockFactory@be37cd2),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1748424 T3857 C632 P51222 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1748425 T3857 C632 P51222 oass.SolrIndexSearcher.<init> Opening Searcher@6ac61040 main
[junit4:junit4] 2> 1748425 T3857 C632 P51222 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1748426 T3865 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6ac61040 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1748427 T3857 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> C629_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:58107_, base_url=http://127.0.0.1:58107}
[junit4:junit4] 2> 1748430 T3869 C629 P58107 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C630_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:19314_, base_url=http://127.0.0.1:19314}
[junit4:junit4] 2> 1748430 T3886 C630 P19314 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1748431 T3869 C629 P58107 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@43bf1e8b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e13d574),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@43bf1e8b lockFactory=org.apache.lucene.store.NativeFSLockFactory@7e13d574),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1748432 T3886 C630 P19314 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e4480e6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@29f49a72),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@1e4480e6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@29f49a72),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1748432 T3869 C629 P58107 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1748432 T3886 C630 P19314 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1748433 T3869 C629 P58107 oass.SolrIndexSearcher.<init> Opening Searcher@419ef1b main
[junit4:junit4] 2> 1748435 T3886 C630 P19314 oass.SolrIndexSearcher.<init> Opening Searcher@760827d4 main
[junit4:junit4] 2> 1748436 T3869 C629 P58107 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1748436 T3886 C630 P19314 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1748437 T3881 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@419ef1b main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1748437 T3898 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@760827d4 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1748438 T3869 C629 P58107 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> 1748438 T3886 C630 P19314 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> 1748439 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 25
[junit4:junit4] 2> 1748440 T3805 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1748443 T3842 C631 P29887 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> 1748445 T3870 C629 P58107 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> 1748448 T3858 C632 P51222 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 1748450 T3887 C630 P19314 oasc.SolrCore.execute [collection1] webapp= path=/select params={tests=checkShardConsistency&q=*:*&distrib=false&wt=javabin&version=2&rows=0} hits=0 status=0 QTime=1
[junit4:junit4] 2> 1750458 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436395252688617472)} 0 2
[junit4:junit4] 2> 1750472 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1436395252695957504&update.from=http://127.0.0.1:29887/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436395252695957504)} 0 3
[junit4:junit4] 2> 1750474 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1436395252700151808&update.from=http://127.0.0.1:51222/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1436395252700151808)} 0 2
[junit4:junit4] 2> 1750475 T3857 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1436395252700151808)} 0 9
[junit4:junit4] 2> 1750476 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1436395252695957504)} 0 14
[junit4:junit4] 2> 1750488 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1436395252721123328)]} 0 1
[junit4:junit4] 2> 1750497 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1436395252727414784)]} 0 1
[junit4:junit4] 2> 1750498 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1436395252727414784)]} 0 5
[junit4:junit4] 2> 1750499 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0]} 0 8
[junit4:junit4] 2> 1750503 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1436395252736851968)]} 0 1
[junit4:junit4] 2> 1750510 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1436395252741046272)]} 0 1
[junit4:junit4] 2> 1750510 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1436395252741046272)]} 0 4
[junit4:junit4] 2> 1750514 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1436395252748386304)]} 0 1
[junit4:junit4] 2> 1750524 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1436395252755726336)]} 0 1
[junit4:junit4] 2> 1750525 T3857 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[2 (1436395252755726336)]} 0 5
[junit4:junit4] 2> 1750526 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2]} 0 9
[junit4:junit4] 2> 1750529 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1436395252764114944)]} 0 1
[junit4:junit4] 2> 1750540 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1436395252772503552)]} 0 1
[junit4:junit4] 2> 1750541 T3857 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[3 (1436395252772503552)]} 0 5
[junit4:junit4] 2> 1750542 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3]} 0 10
[junit4:junit4] 2> 1750546 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1436395252781940736)]} 0 1
[junit4:junit4] 2> 1750554 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1436395252787183616)]} 0 1
[junit4:junit4] 2> 1750555 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1436395252787183616)]} 0 5
[junit4:junit4] 2> 1750559 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1436395252795572224)]} 0 1
[junit4:junit4] 2> 1750565 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1436395252798717952)]} 0 1
[junit4:junit4] 2> 1750566 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1436395252798717952)]} 0 5
[junit4:junit4] 2> 1750570 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1436395252807106560)]} 0 1
[junit4:junit4] 2> 1750578 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1436395252811300864)]} 0 1
[junit4:junit4] 2> 1750579 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1436395252811300864)]} 0 6
[junit4:junit4] 2> 1750583 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1436395252820738048)]} 0 1
[junit4:junit4] 2> 1750593 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1436395252827029504)]} 0 1
[junit4:junit4] 2> 1750594 T3857 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[7 (1436395252827029504)]} 0 6
[junit4:junit4] 2> 1750594 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7]} 0 8
[junit4:junit4] 2> 1750598 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1436395252836466688)]} 0 1
[junit4:junit4] 2> 1750608 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1436395252843806720)]} 0 1
[junit4:junit4] 2> 1750609 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1436395252843806720)]} 0 5
[junit4:junit4] 2> 1750610 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8]} 0 9
[junit4:junit4] 2> 1750614 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1436395252853243904)]} 0 1
[junit4:junit4] 2> 1750624 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1436395252860583936)]} 0 1
[junit4:junit4] 2> 1750625 T3857 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[9 (1436395252860583936)]} 0 5
[junit4:junit4] 2> 1750626 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9]} 0 9
[junit4:junit4] 2> 1750628 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1436395252867923968)]} 0 1
[junit4:junit4] 2> 1750637 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1436395252874215424)]} 0 1
[junit4:junit4] 2> 1750638 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[10 (1436395252874215424)]} 0 5
[junit4:junit4] 2> 1750639 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10]} 0 9
[junit4:junit4] 2> 1750644 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1436395252884701184)]} 0 1
[junit4:junit4] 2> 1750654 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1436395252893089792)]} 0 1
[junit4:junit4] 2> 1750655 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[11 (1436395252893089792)]} 0 5
[junit4:junit4] 2> 1750655 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11]} 0 7
[junit4:junit4] 2> 1750660 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1436395252901478400)]} 0 1
[junit4:junit4] 2> 1750667 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1436395252905672704)]} 0 1
[junit4:junit4] 2> 1750668 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1436395252905672704)]} 0 5
[junit4:junit4] 2> 1750673 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1436395252915109888)]} 0 1
[junit4:junit4] 2> 1750681 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1436395252920352768)]} 0 1
[junit4:junit4] 2> 1750682 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1436395252920352768)]} 0 5
[junit4:junit4] 2> 1750686 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1436395252928741376)]} 0 1
[junit4:junit4] 2> 1750695 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1436395252935032832)]} 0 1
[junit4:junit4] 2> 1750696 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[14 (1436395252935032832)]} 0 4
[junit4:junit4] 2> 1750696 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14]} 0 8
[junit4:junit4] 2> 1750700 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1436395252944470016)]} 0 1
[junit4:junit4] 2> 1750710 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1436395252950761472)]} 0 1
[junit4:junit4] 2> 1750711 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[15 (1436395252950761472)]} 0 5
[junit4:junit4] 2> 1750712 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15]} 0 9
[junit4:junit4] 2> 1750716 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1436395252960198656)]} 0 1
[junit4:junit4] 2> 1750724 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1436395252964392960)]} 0 1
[junit4:junit4] 2> 1750725 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1436395252964392960)]} 0 6
[junit4:junit4] 2> 1750728 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1436395252972781568)]} 0 1
[junit4:junit4] 2> 1750734 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1436395252975927296)]} 0 1
[junit4:junit4] 2> 1750734 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1436395252975927296)]} 0 4
[junit4:junit4] 2> 1750739 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1436395252984315904)]} 0 1
[junit4:junit4] 2> 1750749 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1436395252991655936)]} 0 1
[junit4:junit4] 2> 1750749 T3857 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[18 (1436395252991655936)]} 0 4
[junit4:junit4] 2> 1750750 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18]} 0 8
[junit4:junit4] 2> 1750755 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1436395253001093120)]} 0 1
[junit4:junit4] 2> 1750766 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1436395253009481728)]} 0 1
[junit4:junit4] 2> 1750767 T3857 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[19 (1436395253009481728)]} 0 5
[junit4:junit4] 2> 1750768 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19]} 0 9
[junit4:junit4] 2> 1750773 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1436395253019967488)]} 0 1
[junit4:junit4] 2> 1750782 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1436395253025210368)]} 0 1
[junit4:junit4] 2> 1750783 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1436395253025210368)]} 0 6
[junit4:junit4] 2> 1750786 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1436395253033598976)]} 0 1
[junit4:junit4] 2> 1750792 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1436395253036744704)]} 0 1
[junit4:junit4] 2> 1750792 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1436395253036744704)]} 0 4
[junit4:junit4] 2> 1750796 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1436395253044084736)]} 0 1
[junit4:junit4] 2> 1750806 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1436395253051424768)]} 0 1
[junit4:junit4] 2> 1750807 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[22 (1436395253051424768)]} 0 5
[junit4:junit4] 2> 1750807 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22]} 0 8
[junit4:junit4] 2> 1750811 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1436395253059813376)]} 0 1
[junit4:junit4] 2> 1750818 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1436395253064007680)]} 0 1
[junit4:junit4] 2> 1750819 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1436395253064007680)]} 0 5
[junit4:junit4] 2> 1750823 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1436395253072396288)]} 0 1
[junit4:junit4] 2> 1750835 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1436395253080784896)]} 0 1
[junit4:junit4] 2> 1750836 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[24 (1436395253080784896)]} 0 6
[junit4:junit4] 2> 1750836 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24]} 0 10
[junit4:junit4] 2> 1750840 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1436395253090222080)]} 0 1
[junit4:junit4] 2> 1750847 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1436395253094416384)]} 0 1
[junit4:junit4] 2> 1750847 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1436395253094416384)]} 0 4
[junit4:junit4] 2> 1750851 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1436395253101756416)]} 0 1
[junit4:junit4] 2> 1750858 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1436395253105950720)]} 0 1
[junit4:junit4] 2> 1750859 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1436395253105950720)]} 0 5
[junit4:junit4] 2> 1750863 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1436395253115387904)]} 0 1
[junit4:junit4] 2> 1750873 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1436395253121679360)]} 0 1
[junit4:junit4] 2> 1750874 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[27 (1436395253121679360)]} 0 5
[junit4:junit4] 2> 1750875 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27]} 0 9
[junit4:junit4] 2> 1750880 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1436395253132165120)]} 0 1
[junit4:junit4] 2> 1750890 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1436395253139505152)]} 0 1
[junit4:junit4] 2> 1750891 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[28 (1436395253139505152)]} 0 5
[junit4:junit4] 2> 1750892 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28]} 0 9
[junit4:junit4] 2> 1750896 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1436395253148942336)]} 0 1
[junit4:junit4] 2> 1750902 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1436395253152088064)]} 0 1
[junit4:junit4] 2> 1750903 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1436395253152088064)]} 0 5
[junit4:junit4] 2> 1750907 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1436395253160476672)]} 0 1
[junit4:junit4] 2> 1750914 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1436395253164670976)]} 0 1
[junit4:junit4] 2> 1750915 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1436395253164670976)]} 0 5
[junit4:junit4] 2> 1750919 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1436395253173059584)]} 0 1
[junit4:junit4] 2> 1750926 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1436395253177253888)]} 0 1
[junit4:junit4] 2> 1750927 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1436395253177253888)]} 0 5
[junit4:junit4] 2> 1750931 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1436395253185642496)]} 0 1
[junit4:junit4] 2> 1750939 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1436395253189836800)]} 0 1
[junit4:junit4] 2> 1750940 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1436395253189836800)]} 0 6
[junit4:junit4] 2> 1750943 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1436395253199273984)]} 0 1
[junit4:junit4] 2> 1750950 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1436395253202419712)]} 0 1
[junit4:junit4] 2> 1750950 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1436395253202419712)]} 0 4
[junit4:junit4] 2> 1750954 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1436395253209759744)]} 0 1
[junit4:junit4] 2> 1750960 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1436395253212905472)]} 0 1
[junit4:junit4] 2> 1750960 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1436395253212905472)]} 0 4
[junit4:junit4] 2> 1750964 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1436395253220245504)]} 0 1
[junit4:junit4] 2> 1750971 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1436395253224439808)]} 0 1
[junit4:junit4] 2> 1750972 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1436395253224439808)]} 0 5
[junit4:junit4] 2> 1750976 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1436395253232828416)]} 0 1
[junit4:junit4] 2> 1750986 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1436395253240168448)]} 0 1
[junit4:junit4] 2> 1750987 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[36 (1436395253240168448)]} 0 5
[junit4:junit4] 2> 1750988 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36]} 0 9
[junit4:junit4] 2> 1750993 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1436395253251702784)]} 0 1
[junit4:junit4] 2> 1751004 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1436395253257994240)]} 0 1
[junit4:junit4] 2> 1751009 T3857 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[37 (1436395253257994240)]} 0 10
[junit4:junit4] 2> 1751011 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37]} 0 15
[junit4:junit4] 2> 1751020 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1436395253280014336)]} 0 1
[junit4:junit4] 2> 1751030 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1436395253287354368)]} 0 1
[junit4:junit4] 2> 1751031 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[38 (1436395253287354368)]} 0 5
[junit4:junit4] 2> 1751032 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38]} 0 9
[junit4:junit4] 2> 1751036 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1436395253295742976)]} 0 1
[junit4:junit4] 2> 1751046 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1436395253303083008)]} 0 1
[junit4:junit4] 2> 1751047 T3857 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[39 (1436395253303083008)]} 0 5
[junit4:junit4] 2> 1751048 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39]} 0 9
[junit4:junit4] 2> 1751052 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1436395253312520192)]} 0 1
[junit4:junit4] 2> 1751059 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1436395253316714496)]} 0 1
[junit4:junit4] 2> 1751060 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1436395253316714496)]} 0 5
[junit4:junit4] 2> 1751063 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1436395253324054528)]} 0 1
[junit4:junit4] 2> 1751073 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1436395253331394560)]} 0 1
[junit4:junit4] 2> 1751074 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[41 (1436395253331394560)]} 0 5
[junit4:junit4] 2> 1751074 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41]} 0 8
[junit4:junit4] 2> 1751078 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1436395253339783168)]} 0 1
[junit4:junit4] 2> 1751088 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1436395253347123200)]} 0 1
[junit4:junit4] 2> 1751089 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[42 (1436395253347123200)]} 0 5
[junit4:junit4] 2> 1751090 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42]} 0 9
[junit4:junit4] 2> 1751093 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1436395253355511808)]} 0 1
[junit4:junit4] 2> 1751099 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1436395253358657536)]} 0 1
[junit4:junit4] 2> 1751100 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1436395253358657536)]} 0 5
[junit4:junit4] 2> 1751104 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1436395253367046144)]} 0 1
[junit4:junit4] 2> 1751110 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1436395253370191872)]} 0 1
[junit4:junit4] 2> 1751110 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1436395253370191872)]} 0 4
[junit4:junit4] 2> 1751114 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1436395253377531904)]} 0 1
[junit4:junit4] 2> 1751124 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1436395253384871936)]} 0 1
[junit4:junit4] 2> 1751125 T3857 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[45 (1436395253384871936)]} 0 5
[junit4:junit4] 2> 1751126 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45]} 0 9
[junit4:junit4] 2> 1751130 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1436395253394309120)]} 0 1
[junit4:junit4] 2> 1751141 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1436395253401649152)]} 0 1
[junit4:junit4] 2> 1751142 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[46 (1436395253401649152)]} 0 6
[junit4:junit4] 2> 1751143 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46]} 0 10
[junit4:junit4] 2> 1751146 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1436395253411086336)]} 0 1
[junit4:junit4] 2> 1751154 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1436395253416329216)]} 0 1
[junit4:junit4] 2> 1751154 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1436395253416329216)]} 0 4
[junit4:junit4] 2> 1751158 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1436395253423669248)]} 0 1
[junit4:junit4] 2> 1751165 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1436395253427863552)]} 0 1
[junit4:junit4] 2> 1751166 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1436395253427863552)]} 0 5
[junit4:junit4] 2> 1751171 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1436395253437300736)]} 0 1
[junit4:junit4] 2> 1751178 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1436395253441495040)]} 0 1
[junit4:junit4] 2> 1751179 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1436395253441495040)]} 0 5
[junit4:junit4] 2> 1751182 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1436395253448835072)]} 0 1
[junit4:junit4] 2> 1751193 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1436395253457223680)]} 0 1
[junit4:junit4] 2> 1751194 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[50 (1436395253457223680)]} 0 5
[junit4:junit4] 2> 1751195 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50]} 0 10
[junit4:junit4] 2> 1751199 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1436395253466660864)]} 0 1
[junit4:junit4] 2> 1751209 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1436395253474000896)]} 0 1
[junit4:junit4] 2> 1751210 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[51 (1436395253474000896)]} 0 5
[junit4:junit4] 2> 1751211 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51]} 0 9
[junit4:junit4] 2> 1751214 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1436395253482389504)]} 0 1
[junit4:junit4] 2> 1751221 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1436395253485535232)]} 0 1
[junit4:junit4] 2> 1751222 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1436395253485535232)]} 0 6
[junit4:junit4] 2> 1751225 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1436395253493923840)]} 0 1
[junit4:junit4] 2> 1751235 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1436395253501263872)]} 0 1
[junit4:junit4] 2> 1751235 T3857 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[53 (1436395253501263872)]} 0 4
[junit4:junit4] 2> 1751236 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53]} 0 8
[junit4:junit4] 2> 1751240 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1436395253509652480)]} 0 1
[junit4:junit4] 2> 1751248 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1436395253513846784)]} 0 1
[junit4:junit4] 2> 1751248 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1436395253513846784)]} 0 5
[junit4:junit4] 2> 1751254 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1436395253524332544)]} 0 1
[junit4:junit4] 2> 1751263 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1436395253530624000)]} 0 1
[junit4:junit4] 2> 1751264 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[55 (1436395253530624000)]} 0 5
[junit4:junit4] 2> 1751265 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55]} 0 8
[junit4:junit4] 2> 1751268 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1436395253539012608)]} 0 1
[junit4:junit4] 2> 1751275 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1436395253543206912)]} 0 1
[junit4:junit4] 2> 1751276 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1436395253543206912)]} 0 5
[junit4:junit4] 2> 1751280 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1436395253551595520)]} 0 1
[junit4:junit4] 2> 1751287 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1436395253555789824)]} 0 1
[junit4:junit4] 2> 1751287 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1436395253555789824)]} 0 4
[junit4:junit4] 2> 1751291 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1436395253563129856)]} 0 1
[junit4:junit4] 2> 1751298 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1436395253567324160)]} 0 1
[junit4:junit4] 2> 1751299 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1436395253567324160)]} 0 5
[junit4:junit4] 2> 1751302 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1436395253574664192)]} 0 1
[junit4:junit4] 2> 1751311 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1436395253580955648)]} 0 1
[junit4:junit4] 2> 1751312 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[59 (1436395253580955648)]} 0 5
[junit4:junit4] 2> 1751312 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59]} 0 7
[junit4:junit4] 2> 1751316 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1436395253589344256)]} 0 1
[junit4:junit4] 2> 1751322 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1436395253592489984)]} 0 1
[junit4:junit4] 2> 1751323 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1436395253592489984)]} 0 5
[junit4:junit4] 2> 1751326 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1436395253599830016)]} 0 1
[junit4:junit4] 2> 1751333 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1436395253604024320)]} 0 1
[junit4:junit4] 2> 1751334 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1436395253604024320)]} 0 5
[junit4:junit4] 2> 1751338 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1436395253612412928)]} 0 1
[junit4:junit4] 2> 1751345 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[62 (1436395253616607232)]} 0 1
[junit4:junit4] 2> 1751346 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1436395253616607232)]} 0 5
[junit4:junit4] 2> 1751349 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1436395253623947264)]} 0 1
[junit4:junit4] 2> 1751356 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[63 (1436395253628141568)]} 0 1
[junit4:junit4] 2> 1751357 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1436395253628141568)]} 0 5
[junit4:junit4] 2> 1751361 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1436395253636530176)]} 0 1
[junit4:junit4] 2> 1751372 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[64 (1436395253644918784)]} 0 1
[junit4:junit4] 2> 1751372 T3843 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[64 (1436395253644918784)]} 0 4
[junit4:junit4] 2> 1751373 T3859 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64]} 0 8
[junit4:junit4] 2> 1751377 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1436395253653307392)]} 0 1
[junit4:junit4] 2> 1751384 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[65 (1436395253657501696)]} 0 1
[junit4:junit4] 2> 1751385 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1436395253657501696)]} 0 5
[junit4:junit4] 2> 1751389 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1436395253665890304)]} 0 1
[junit4:junit4] 2> 1751397 T3869 C629 P58107 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[66 (1436395253671133184)]} 0 1
[junit4:junit4] 2> 1751397 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1436395253671133184)]} 0 4
[junit4:junit4] 2> 1751400 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1436395253678473216)]} 0 0
[junit4:junit4] 2> 1751410 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[67 (1436395253684764672)]} 0 1
[junit4:junit4] 2> 1751410 T3857 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[67 (1436395253684764672)]} 0 4
[junit4:junit4] 2> 1751411 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67]} 0 8
[junit4:junit4] 2> 1751415 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1436395253693153280)]} 0 1
[junit4:junit4] 2> 1751425 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[68 (1436395253700493312)]} 0 1
[junit4:junit4] 2> 1751425 T3857 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[68 (1436395253700493312)]} 0 4
[junit4:junit4] 2> 1751426 T3841 C631 P29887 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68]} 0 9
[junit4:junit4] 2> 1751431 T3817 C633 P49448 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69 (1436395253709930496)]} 0 1
[junit4:junit4] 2> 1751443 T3888 C630 P19314 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:51222/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[69 (1436395253718319104)]} 0 1
[junit4:junit4] 2> 1751444 T3857 C632 P51222 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:29887/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[69 (14363
[...truncated too long message...]
itTest-1369853234261/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4/index;done=false>>]
[junit4:junit4] 2> 2008881 T3896 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4/index
[junit4:junit4] 2> 2008882 T3896 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4;done=false>>]
[junit4:junit4] 2> 2008882 T3896 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369853234261/jetty4
[junit4:junit4] 2> 2008882 T3896 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 2008883 T3896 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election/89774701561184268-127.0.0.1:19314__collection1-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> 2008883 T3896 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> 2008884 T3896 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2008884 T3896 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2008884 T3896 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> 2008884 T3896 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2008884 T3896 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=Lucene42: {id=PostingsFormat(name=TestBloomFilteredLucene41Postings), _version_=PostingsFormat(name=NestedPulsing)}, docValues:{}, sim=RandomSimilarityProvider(queryNorm=false,coord=yes): {}, locale=tr_TR, timezone=Pacific/Guam
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=16,threads=3,free=126452928,total=509607936
[junit4:junit4] 2> NOTE: All tests run in this JVM: [PrimUtilsTest, TestDocumentBuilder, BinaryUpdateRequestHandlerTest, RegexBoostProcessorTest, SyncSliceTest, OverseerTest, SchemaVersionSpecificBehaviorTest, ScriptEngineTest, TestSurroundQueryParser, TestWriterPerf, ExternalFileFieldSortTest, QueryParsingTest, PolyFieldTest, BadCopyFieldTest, TestSchemaResource, TestSolrDeletionPolicy1, PreAnalyzedUpdateProcessorTest, TestCoreContainer, TestSearchPerf, MBeansHandlerTest, DistributedSpellCheckComponentTest, TestManagedSchemaFieldResource, PluginInfoTest, UnloadDistributedZkTest, SuggesterTest, DirectSolrConnectionTest, SolrCoreTest, TestXIncludeConfig, ZkCLITest, IndexSchemaTest, TestPropInjectDefaults, TestPhraseSuggestions, SystemInfoHandlerTest, SynonymTokenizerTest, SpatialFilterTest, FieldMutatingUpdateProcessorTest, UUIDFieldTest, TestPHPSerializedResponseWriter, ReturnFieldsTest, TestValueSourceCache, TermVectorComponentTest, TestSweetSpotSimilarityFactory, CacheHeaderTest, TestLMDirichletSimilarityFactory, QueryResultKeyTest, TestDocSet, RecoveryZkTest, BasicFunctionalityTest, FastVectorHighlighterTest, UpdateRequestProcessorFactoryTest, TestFastLRUCache, SoftAutoCommitTest, PrimitiveFieldTypeTest, AutoCommitTest, TestGroupingSearch, RAMDirectoryFactoryTest, ShardSplitTest, SliceStateTest, LoggingHandlerTest, TestPseudoReturnFields, SolrInfoMBeanTest, AliasIntegrationTest, QueryElevationComponentTest, ResponseLogComponentTest, LukeRequestHandlerTest, QueryEqualityTest, DocumentBuilderTest, TestTrie, TestSort, SOLR749Test, DirectUpdateHandlerOptimizeTest, TestReplicationHandler, LeaderElectionTest, TestZkChroot, TestRandomDVFaceting, TestMultiCoreConfBootstrap, TestStressVersions, DistributedTermsComponentTest, TestRangeQuery, SimpleFacetsTest, TestSolr4Spatial, SpellCheckComponentTest, SolrCmdDistributorTest, PeerSyncTest, BadIndexSchemaTest, TestFunctionQuery, TestBadConfig, OverseerCollectionProcessorTest, DistributedQueryElevationComponentTest, SimplePostToolTest, TestExtendedDismaxParser, SuggesterFSTTest, SolrRequestParserTest, DocValuesTest, TestCSVLoader, SolrCoreCheckLockOnStartupTest, TestWordDelimiterFilterFactory, TestRemoteStreaming, DistanceFunctionTest, IndexBasedSpellCheckerTest, TestQueryUtils, TestQueryTypes, FileBasedSpellCheckerTest, XmlUpdateRequestHandlerTest, TestIndexingPerformance, RequiredFieldsTest, IndexSchemaRuntimeFieldTest, JSONWriterTest, JsonLoaderTest, CSVRequestHandlerTest, CoreContainerCoreInitFailuresTest, UpdateParamsTest, TestSolrIndexConfig, CopyFieldTest, TestSolrDeletionPolicy2, MultiTermTest, SampleTest, TestBinaryField, NumericFieldsTest, MinimalSchemaTest, TestConfig, TestFuzzyAnalyzedSuggestions, TestSolrCoreProperties, TestPostingsSolrHighlighter, TestCharFilters, EchoParamsTest, TestDFRSimilarityFactory, TestPerFieldSimilarity, TestNumberUtils, TestLMJelinekMercerSimilarityFactory, TestIBSimilarityFactory, TestDefaultSimilarityFactory, TestFastWriter, LegacyHTMLStripCharFilterTest, TestPluginEnable, TimeZoneUtilsTest, ResourceLoaderTest, TestFastOutputStream, ChaosMonkeyNothingIsSafeTest, PreAnalyzedFieldTest, TestSystemIdResolver, TestSuggestSpellingConverter, DateFieldTest, SpellingQueryConverterTest, DOMUtilTest, ClusterStateTest, TestLRUCache, TestUtils, FileUtilsTest, CircularListTest, TestRTGBase, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J0 in 285.25s, 1 test, 1 error <<< FAILURES!
[...truncated 10 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:380: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:360: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/lucene/common-build.xml:1240: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-trunk-Java7/lucene/common-build.xml:884: There were test failures: 295 suites, 1232 tests, 1 error, 13 ignored (7 assumptions)
Total time: 54 minutes 30 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure