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/06/10 17:05:20 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1698 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1698/
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:57102 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:57102 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([284B38D08484C89D:A9ADB6C8F3DBA8A1]: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:228)
at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:616)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:679)
Build Log:
[...truncated 9611 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 1724278 T3269 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 1724283 T3269 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./solrtest-ChaosMonkeyShardSplitTest-1370876415217
[junit4:junit4] 2> 1724284 T3269 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1724285 T3270 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1724386 T3269 oasc.ZkTestServer.run start zk server on port:15278
[junit4:junit4] 2> 1724387 T3269 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1724392 T3276 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@73abbe98 name:ZooKeeperConnection Watcher:127.0.0.1:15278 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1724392 T3269 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1724392 T3269 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1724409 T3269 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1724411 T3278 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@42c33be7 name:ZooKeeperConnection Watcher:127.0.0.1:15278/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1724412 T3269 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1724412 T3269 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1724423 T3269 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1724427 T3269 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1724429 T3269 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1724439 T3269 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1724440 T3269 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1724450 T3269 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 1724451 T3269 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1724555 T3269 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1724556 T3269 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1724566 T3269 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 1724567 T3269 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1724570 T3269 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 1724570 T3269 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1724573 T3269 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1724574 T3269 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1724577 T3269 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1724578 T3269 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1724581 T3269 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1724581 T3269 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1724584 T3269 oasc.AbstractZkTestCase.putConfig put /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1724585 T3269 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1724870 T3269 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1724875 T3269 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:15284
[junit4:junit4] 2> 1724875 T3269 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1724876 T3269 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1724876 T3269 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370876415532
[junit4:junit4] 2> 1724877 T3269 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370876415532/solr.xml
[junit4:junit4] 2> 1724877 T3269 oasc.CoreContainer.<init> New CoreContainer 1248497872
[junit4:junit4] 2> 1724878 T3269 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370876415532/'
[junit4:junit4] 2> 1724878 T3269 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370876415532/'
[junit4:junit4] 2> 1724995 T3269 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1724996 T3269 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1724996 T3269 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1724997 T3269 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1724997 T3269 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1724998 T3269 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1724998 T3269 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1724999 T3269 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1724999 T3269 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1725000 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1725016 T3269 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1725017 T3269 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:15278/solr
[junit4:junit4] 2> 1725017 T3269 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1725018 T3269 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1725021 T3289 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4acb5258 name:ZooKeeperConnection Watcher:127.0.0.1:15278 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1725022 T3269 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1725034 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1725044 T3269 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1725046 T3291 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4b19fae1 name:ZooKeeperConnection Watcher:127.0.0.1:15278/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1725046 T3269 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1725050 T3269 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1725058 T3269 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1725066 T3269 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1725068 T3269 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:15284_
[junit4:junit4] 2> 1725076 T3269 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:15284_
[junit4:junit4] 2> 1725079 T3269 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1725092 T3269 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1725101 T3269 oasc.Overseer.start Overseer (id=89841756748120067-127.0.0.1:15284_-n_0000000000) starting
[junit4:junit4] 2> 1725123 T3269 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1725133 T3293 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1725133 T3269 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1725142 T3269 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1725144 T3269 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1725147 T3292 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1725151 T3294 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1725151 T3294 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1726650 T3292 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1726651 T3292 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:15284_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:15284"}
[junit4:junit4] 2> 1726651 T3292 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1726652 T3292 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1726670 T3291 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> 1727154 T3294 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370876415532/collection1
[junit4:junit4] 2> 1727154 T3294 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1727155 T3294 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1727155 T3294 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1727157 T3294 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370876415532/collection1/'
[junit4:junit4] 2> 1727158 T3294 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370876415532/collection1/lib/README' to classloader
[junit4:junit4] 2> 1727158 T3294 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370876415532/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1727210 T3294 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1727278 T3294 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1727379 T3294 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1727384 T3294 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1727969 T3294 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1727974 T3294 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1727976 T3294 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1727981 T3294 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1728007 T3294 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1728007 T3294 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1370876415532/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/control/data/
[junit4:junit4] 2> 1728007 T3294 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a0430b6
[junit4:junit4] 2> 1728008 T3294 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1728008 T3294 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/control/data
[junit4:junit4] 2> 1728009 T3294 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/control/data/index/
[junit4:junit4] 2> 1728009 T3294 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1728009 T3294 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/control/data/index
[junit4:junit4] 2> 1728014 T3294 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3ca5e96 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e2e2c88),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1728015 T3294 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1728017 T3294 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1728017 T3294 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1728018 T3294 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1728018 T3294 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1728019 T3294 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1728019 T3294 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1728019 T3294 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1728020 T3294 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1728020 T3294 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1728031 T3294 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1728039 T3294 oass.SolrIndexSearcher.<init> Opening Searcher@3e23d64d main
[junit4:junit4] 2> 1728039 T3294 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/control/data/tlog
[junit4:junit4] 2> 1728040 T3294 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1728040 T3294 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1728044 T3295 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3e23d64d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1728045 T3294 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1728045 T3294 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:15284 collection:control_collection shard:shard1
[junit4:junit4] 2> 1728046 T3294 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1728066 T3294 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1728075 T3294 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1728076 T3294 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1728076 T3294 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:15284/collection1/
[junit4:junit4] 2> 1728076 T3294 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1728076 T3294 oasc.SyncStrategy.syncToMe http://127.0.0.1:15284/collection1/ has no replicas
[junit4:junit4] 2> 1728077 T3294 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:15284/collection1/
[junit4:junit4] 2> 1728077 T3294 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1728173 T3292 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1728195 T3291 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> 1728244 T3294 oasc.ZkController.register We are http://127.0.0.1:15284/collection1/ and leader is http://127.0.0.1:15284/collection1/
[junit4:junit4] 2> 1728244 T3294 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:15284
[junit4:junit4] 2> 1728244 T3294 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1728244 T3294 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1728245 T3294 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1728246 T3294 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1728247 T3269 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1728248 T3269 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1728248 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1728268 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1728269 T3269 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1728271 T3298 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4b065c1d name:ZooKeeperConnection Watcher:127.0.0.1:15278/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1728271 T3269 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1728273 T3269 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1728275 T3269 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1728609 T3269 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1728611 T3269 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:57102
[junit4:junit4] 2> 1728612 T3269 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1728613 T3269 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1728613 T3269 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370876419208
[junit4:junit4] 2> 1728614 T3269 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370876419208/solr.xml
[junit4:junit4] 2> 1728614 T3269 oasc.CoreContainer.<init> New CoreContainer 462110653
[junit4:junit4] 2> 1728615 T3269 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370876419208/'
[junit4:junit4] 2> 1728615 T3269 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370876419208/'
[junit4:junit4] 2> 1728744 T3269 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1728745 T3269 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1728746 T3269 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1728746 T3269 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1728747 T3269 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1728747 T3269 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1728748 T3269 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1728748 T3269 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1728748 T3269 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1728749 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1728765 T3269 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1728766 T3269 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:15278/solr
[junit4:junit4] 2> 1728766 T3269 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1728767 T3269 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1728770 T3309 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@16255462 name:ZooKeeperConnection Watcher:127.0.0.1:15278 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1728770 T3269 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1728773 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1728786 T3269 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1728788 T3311 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4924baa6 name:ZooKeeperConnection Watcher:127.0.0.1:15278/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1728788 T3269 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1728793 T3269 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1729700 T3292 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1729701 T3292 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:15284__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:15284_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:15284"}
[junit4:junit4] 2> 1729715 T3311 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> 1729715 T3298 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> 1729715 T3291 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> 1729796 T3269 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:57102_
[junit4:junit4] 2> 1729803 T3269 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:57102_
[junit4:junit4] 2> 1729805 T3298 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> 1729806 T3311 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1729806 T3291 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1729806 T3311 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> 1729806 T3291 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> 1729807 T3298 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1729812 T3312 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1729813 T3312 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1731221 T3292 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1731222 T3292 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:57102_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57102"}
[junit4:junit4] 2> 1731222 T3292 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 1731223 T3292 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1731259 T3291 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> 1731259 T3311 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> 1731259 T3298 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> 1731818 T3312 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370876419208/collection1
[junit4:junit4] 2> 1731818 T3312 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1731819 T3312 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1731819 T3312 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1731820 T3312 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370876419208/collection1/'
[junit4:junit4] 2> 1731822 T3312 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370876419208/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1731822 T3312 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370876419208/collection1/lib/README' to classloader
[junit4:junit4] 2> 1731873 T3312 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1731931 T3312 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1732032 T3312 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1732037 T3312 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1732620 T3312 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1732625 T3312 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1732627 T3312 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1732632 T3312 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1732655 T3312 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1732655 T3312 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1370876419208/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty1/
[junit4:junit4] 2> 1732655 T3312 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a0430b6
[junit4:junit4] 2> 1732656 T3312 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1732657 T3312 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty1
[junit4:junit4] 2> 1732657 T3312 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty1/index/
[junit4:junit4] 2> 1732657 T3312 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1732658 T3312 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty1/index
[junit4:junit4] 2> 1732661 T3312 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7f4069c lockFactory=org.apache.lucene.store.NativeFSLockFactory@71d0d8cf),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1732662 T3312 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1732665 T3312 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1732665 T3312 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1732665 T3312 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1732666 T3312 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1732667 T3312 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1732667 T3312 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1732667 T3312 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1732668 T3312 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1732668 T3312 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1732678 T3312 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1732685 T3312 oass.SolrIndexSearcher.<init> Opening Searcher@7e81b8d3 main
[junit4:junit4] 2> 1732686 T3312 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty1/tlog
[junit4:junit4] 2> 1732687 T3312 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1732687 T3312 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1732691 T3313 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7e81b8d3 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1732693 T3312 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1732693 T3312 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:57102 collection:collection1 shard:shard1
[junit4:junit4] 2> 1732694 T3312 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 1732713 T3312 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1732716 T3312 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1732716 T3312 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1732716 T3312 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:57102/collection1/
[junit4:junit4] 2> 1732716 T3312 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1732717 T3312 oasc.SyncStrategy.syncToMe http://127.0.0.1:57102/collection1/ has no replicas
[junit4:junit4] 2> 1732717 T3312 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:57102/collection1/
[junit4:junit4] 2> 1732717 T3312 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1732763 T3292 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1732770 T3311 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> 1732770 T3298 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> 1732770 T3291 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> 1732774 T3312 oasc.ZkController.register We are http://127.0.0.1:57102/collection1/ and leader is http://127.0.0.1:57102/collection1/
[junit4:junit4] 2> 1732774 T3312 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:57102
[junit4:junit4] 2> 1732774 T3312 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1732774 T3312 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1732775 T3312 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1732776 T3312 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1732777 T3269 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1732778 T3269 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1732778 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1733065 T3269 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1733068 T3269 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:18032
[junit4:junit4] 2> 1733069 T3269 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1733069 T3269 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1733070 T3269 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370876423728
[junit4:junit4] 2> 1733070 T3269 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370876423728/solr.xml
[junit4:junit4] 2> 1733070 T3269 oasc.CoreContainer.<init> New CoreContainer 1412730404
[junit4:junit4] 2> 1733071 T3269 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370876423728/'
[junit4:junit4] 2> 1733072 T3269 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370876423728/'
[junit4:junit4] 2> 1733186 T3269 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1733187 T3269 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1733187 T3269 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1733188 T3269 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1733188 T3269 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1733189 T3269 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1733189 T3269 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1733190 T3269 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1733190 T3269 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1733191 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1733207 T3269 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1733208 T3269 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:15278/solr
[junit4:junit4] 2> 1733208 T3269 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1733210 T3269 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1733213 T3325 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4ad9784c name:ZooKeeperConnection Watcher:127.0.0.1:15278 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1733214 T3269 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1733233 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1733247 T3269 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1733249 T3327 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2331a609 name:ZooKeeperConnection Watcher:127.0.0.1:15278/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1733250 T3269 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1733254 T3269 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1734258 T3269 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:18032_
[junit4:junit4] 2> 1734260 T3269 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:18032_
[junit4:junit4] 2> 1734262 T3298 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> 1734263 T3311 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1734264 T3327 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1734264 T3311 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> 1734264 T3291 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1734264 T3298 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1734264 T3291 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> 1734276 T3292 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1734277 T3292 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:57102__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:57102_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:57102"}
[junit4:junit4] 2> 1734279 T3328 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1734280 T3328 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1734297 T3292 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:18032_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18032"}
[junit4:junit4] 2> 1734297 T3292 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1734297 T3292 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1734309 T3298 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> 1734309 T3327 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> 1734309 T3291 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> 1734309 T3311 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> 1735288 T3328 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370876423728/collection1
[junit4:junit4] 2> 1735288 T3328 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1735289 T3328 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1735289 T3328 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1735290 T3328 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370876423728/collection1/'
[junit4:junit4] 2> 1735292 T3328 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370876423728/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1735292 T3328 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370876423728/collection1/lib/README' to classloader
[junit4:junit4] 2> 1735345 T3328 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1735403 T3328 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1735505 T3328 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1735511 T3328 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1736102 T3328 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1736106 T3328 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1736109 T3328 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1736114 T3328 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1736136 T3328 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1736136 T3328 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1370876423728/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty2/
[junit4:junit4] 2> 1736137 T3328 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a0430b6
[junit4:junit4] 2> 1736137 T3328 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1736138 T3328 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty2
[junit4:junit4] 2> 1736138 T3328 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty2/index/
[junit4:junit4] 2> 1736138 T3328 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1736139 T3328 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty2/index
[junit4:junit4] 2> 1736143 T3328 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2263b473 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5bf259cd),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1736143 T3328 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1736146 T3328 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1736146 T3328 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1736147 T3328 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1736148 T3328 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1736148 T3328 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1736148 T3328 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1736149 T3328 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1736149 T3328 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1736150 T3328 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1736160 T3328 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1736168 T3328 oass.SolrIndexSearcher.<init> Opening Searcher@3ae7f469 main
[junit4:junit4] 2> 1736168 T3328 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty2/tlog
[junit4:junit4] 2> 1736169 T3328 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1736169 T3328 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1736174 T3329 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3ae7f469 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1736176 T3328 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1736176 T3328 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:18032 collection:collection1 shard:shard2
[junit4:junit4] 2> 1736177 T3328 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 1736201 T3328 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1736212 T3328 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1736212 T3328 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1736212 T3328 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:18032/collection1/
[junit4:junit4] 2> 1736213 T3328 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1736213 T3328 oasc.SyncStrategy.syncToMe http://127.0.0.1:18032/collection1/ has no replicas
[junit4:junit4] 2> 1736213 T3328 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:18032/collection1/
[junit4:junit4] 2> 1736213 T3328 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1737317 T3292 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1737340 T3298 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> 1737340 T3327 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> 1737340 T3291 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> 1737340 T3311 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> 1737347 T3328 oasc.ZkController.register We are http://127.0.0.1:18032/collection1/ and leader is http://127.0.0.1:18032/collection1/
[junit4:junit4] 2> 1737347 T3328 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:18032
[junit4:junit4] 2> 1737347 T3328 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1737347 T3328 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1737348 T3328 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1737349 T3328 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1737350 T3269 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1737351 T3269 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1737351 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1737700 T3269 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1737703 T3269 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:21453
[junit4:junit4] 2> 1737704 T3269 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1737704 T3269 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1737705 T3269 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370876428301
[junit4:junit4] 2> 1737705 T3269 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370876428301/solr.xml
[junit4:junit4] 2> 1737706 T3269 oasc.CoreContainer.<init> New CoreContainer 422504232
[junit4:junit4] 2> 1737707 T3269 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370876428301/'
[junit4:junit4] 2> 1737707 T3269 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370876428301/'
[junit4:junit4] 2> 1737869 T3269 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1737870 T3269 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1737870 T3269 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1737871 T3269 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1737871 T3269 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1737871 T3269 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1737872 T3269 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1737872 T3269 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1737873 T3269 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1737873 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1737890 T3269 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1737891 T3269 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:15278/solr
[junit4:junit4] 2> 1737891 T3269 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1737892 T3269 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1737901 T3341 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@43185d8c name:ZooKeeperConnection Watcher:127.0.0.1:15278 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1737902 T3269 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1737904 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1737919 T3269 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1737920 T3343 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7ad8ef3 name:ZooKeeperConnection Watcher:127.0.0.1:15278/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1737921 T3269 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1737925 T3269 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1738846 T3292 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1738847 T3292 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:18032__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:18032_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:18032"}
[junit4:junit4] 2> 1738866 T3298 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> 1738866 T3291 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> 1738866 T3311 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> 1738866 T3327 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> 1738866 T3343 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> 1738928 T3269 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:21453_
[junit4:junit4] 2> 1738937 T3269 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:21453_
[junit4:junit4] 2> 1738939 T3298 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> 1738939 T3327 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> 1738939 T3291 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1738939 T3311 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1738939 T3343 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> 1738940 T3311 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> 1738939 T3291 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> 1738940 T3298 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1738946 T3327 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1738947 T3343 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1738951 T3344 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1738952 T3344 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1740371 T3292 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1740372 T3292 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:21453_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:21453"}
[junit4:junit4] 2> 1740372 T3292 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1740372 T3292 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1740387 T3298 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> 1740387 T3291 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> 1740387 T3343 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> 1740387 T3327 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> 1740387 T3311 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> 1740955 T3344 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370876428301/collection1
[junit4:junit4] 2> 1740955 T3344 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1740956 T3344 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1740956 T3344 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1740958 T3344 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370876428301/collection1/'
[junit4:junit4] 2> 1740959 T3344 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370876428301/collection1/lib/README' to classloader
[junit4:junit4] 2> 1740960 T3344 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370876428301/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1741014 T3344 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1741077 T3344 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1741178 T3344 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1741183 T3344 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1741772 T3344 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1741776 T3344 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1741779 T3344 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1741784 T3344 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1741805 T3344 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1741806 T3344 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1370876428301/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty3/
[junit4:junit4] 2> 1741806 T3344 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a0430b6
[junit4:junit4] 2> 1741807 T3344 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1741808 T3344 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty3
[junit4:junit4] 2> 1741808 T3344 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty3/index/
[junit4:junit4] 2> 1741808 T3344 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1741809 T3344 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty3/index
[junit4:junit4] 2> 1741812 T3344 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7a39c335 lockFactory=org.apache.lucene.store.NativeFSLockFactory@315bc9f7),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1741812 T3344 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1741815 T3344 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1741815 T3344 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1741816 T3344 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1741817 T3344 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1741817 T3344 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1741817 T3344 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1741818 T3344 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1741818 T3344 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1741819 T3344 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1741829 T3344 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1741837 T3344 oass.SolrIndexSearcher.<init> Opening Searcher@71834b5e main
[junit4:junit4] 2> 1741837 T3344 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty3/tlog
[junit4:junit4] 2> 1741838 T3344 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1741838 T3344 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1741843 T3345 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@71834b5e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1741845 T3344 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1741845 T3344 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:21453 collection:collection1 shard:shard1
[junit4:junit4] 2> 1741848 T3344 oasc.ZkController.register We are http://127.0.0.1:21453/collection1/ and leader is http://127.0.0.1:57102/collection1/
[junit4:junit4] 2> 1741848 T3344 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:21453
[junit4:junit4] 2> 1741849 T3344 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1741849 T3344 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1222 name=collection1 org.apache.solr.core.SolrCore@3857d30f url=http://127.0.0.1:21453/collection1 node=127.0.0.1:21453_ C1222_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:21453_, base_url=http://127.0.0.1:21453}
[junit4:junit4] 2> 1741849 T3346 C1222 P21453 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1741850 T3344 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1741850 T3346 C1222 P21453 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1741851 T3346 C1222 P21453 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1741851 T3346 C1222 P21453 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1741851 T3269 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1741852 T3269 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1741852 T3346 C1222 P21453 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1741852 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1741880 T3301 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:21453__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1741891 T3292 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1741892 T3292 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:21453__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:21453_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:21453"}
[junit4:junit4] 2> 1741913 T3298 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 T3291 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 T3343 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 T3327 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> 1741916 T3311 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> 1742187 T3269 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1742190 T3269 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:26447
[junit4:junit4] 2> 1742191 T3269 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1742192 T3269 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1742192 T3269 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370876432811
[junit4:junit4] 2> 1742193 T3269 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370876432811/solr.xml
[junit4:junit4] 2> 1742193 T3269 oasc.CoreContainer.<init> New CoreContainer 1209273118
[junit4:junit4] 2> 1742194 T3269 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370876432811/'
[junit4:junit4] 2> 1742194 T3269 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370876432811/'
[junit4:junit4] 2> 1742321 T3269 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1742322 T3269 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1742322 T3269 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1742323 T3269 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1742323 T3269 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1742324 T3269 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1742324 T3269 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1742325 T3269 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1742325 T3269 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1742325 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1742343 T3269 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1742344 T3269 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:15278/solr
[junit4:junit4] 2> 1742344 T3269 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1742345 T3269 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1742348 T3358 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@19f26755 name:ZooKeeperConnection Watcher:127.0.0.1:15278 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1742349 T3269 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1742352 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1742362 T3269 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1742365 T3360 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@725a678f name:ZooKeeperConnection Watcher:127.0.0.1:15278/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1742365 T3269 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1742375 T3269 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1742881 T3301 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:21453__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 1742881 T3301 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:21453__collection1&state=recovering&nodeName=127.0.0.1:21453_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1001
[junit4:junit4] 2> 1743378 T3269 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:26447_
[junit4:junit4] 2> 1743380 T3269 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:26447_
[junit4:junit4] 2> 1743383 T3298 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> 1743383 T3327 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> 1743384 T3311 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1743383 T3343 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> 1743384 T3311 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> 1743384 T3360 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1743384 T3291 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1743385 T3298 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1743385 T3291 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> 1743386 T3327 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1743394 T3343 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1743399 T3361 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1743399 T3361 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1743417 T3292 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1743418 T3292 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:26447_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:26447"}
[junit4:junit4] 2> 1743418 T3292 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1743418 T3292 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1743443 T3298 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> 1743443 T3291 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> 1743443 T3343 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> 1743443 T3360 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> 1743443 T3327 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> 1743443 T3311 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> 1744402 T3361 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370876432811/collection1
[junit4:junit4] 2> 1744402 T3361 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1744403 T3361 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1744403 T3361 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1744405 T3361 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370876432811/collection1/'
[junit4:junit4] 2> 1744406 T3361 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370876432811/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1744406 T3361 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370876432811/collection1/lib/README' to classloader
[junit4:junit4] 2> 1744455 T3361 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1744512 T3361 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1744613 T3361 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1744618 T3361 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C1223 name=collection1 org.apache.solr.core.SolrCore@3857d30f url=http://127.0.0.1:21453/collection1 node=127.0.0.1:21453_ C1223_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:21453_, base_url=http://127.0.0.1:21453}
[junit4:junit4] 2> 1744883 T3346 C1223 P21453 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:57102/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1744883 T3346 C1223 P21453 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:21453 START replicas=[http://127.0.0.1:57102/collection1/] nUpdates=100
[junit4:junit4] 2> 1744884 T3346 C1223 P21453 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1744884 T3346 C1223 P21453 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1744884 T3346 C1223 P21453 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1744884 T3346 C1223 P21453 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1744885 T3346 C1223 P21453 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1744885 T3346 C1223 P21453 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:57102/collection1/. core=collection1
[junit4:junit4] 2> 1744885 T3346 C1223 P21453 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1224 name=collection1 org.apache.solr.core.SolrCore@5a8f61f url=http://127.0.0.1:57102/collection1 node=127.0.0.1:57102_ C1224_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57102_, base_url=http://127.0.0.1:57102, leader=true}
[junit4:junit4] 2> 1744892 T3302 C1224 P57102 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1744896 T3303 C1224 P57102 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1744899 T3303 C1224 P57102 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7f4069c lockFactory=org.apache.lucene.store.NativeFSLockFactory@71d0d8cf),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1744899 T3303 C1224 P57102 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1744900 T3303 C1224 P57102 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7f4069c lockFactory=org.apache.lucene.store.NativeFSLockFactory@71d0d8cf),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7f4069c lockFactory=org.apache.lucene.store.NativeFSLockFactory@71d0d8cf),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1744900 T3303 C1224 P57102 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1744901 T3303 C1224 P57102 oass.SolrIndexSearcher.<init> Opening Searcher@4f3bf16e realtime
[junit4:junit4] 2> 1744901 T3303 C1224 P57102 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1744902 T3303 C1224 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 1744903 T3346 C1223 P21453 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1744903 T3346 C1223 P21453 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1744905 T3304 C1224 P57102 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1744905 T3304 C1224 P57102 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 1744906 T3346 C1223 P21453 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1744906 T3346 C1223 P21453 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1744906 T3346 C1223 P21453 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1744909 T3304 C1224 P57102 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> 1744910 T3346 C1223 P21453 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1744912 T3346 C1223 P21453 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty3/index.20130610170035843
[junit4:junit4] 2> 1744912 T3346 C1223 P21453 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1340310e lockFactory=org.apache.lucene.store.NativeFSLockFactory@51ecc16d) fullCopy=false
[junit4:junit4] 2> 1744914 T3304 C1224 P57102 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> 1744915 T3346 C1223 P21453 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1744922 T3346 C1223 P21453 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1744922 T3346 C1223 P21453 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1744924 T3346 C1223 P21453 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7a39c335 lockFactory=org.apache.lucene.store.NativeFSLockFactory@315bc9f7),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7a39c335 lockFactory=org.apache.lucene.store.NativeFSLockFactory@315bc9f7),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1744925 T3346 C1223 P21453 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1744925 T3346 C1223 P21453 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1744925 T3346 C1223 P21453 oass.SolrIndexSearcher.<init> Opening Searcher@53692818 main
[junit4:junit4] 2> 1744926 T3345 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@53692818 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1744927 T3346 C1223 P21453 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty3/index.20130610170035843 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty3/index.20130610170035843;done=true>>]
[junit4:junit4] 2> 1744928 T3346 C1223 P21453 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty3/index.20130610170035843
[junit4:junit4] 2> 1744928 T3346 C1223 P21453 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty3/index.20130610170035843
[junit4:junit4] 2> 1744928 T3346 C1223 P21453 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1744928 T3346 C1223 P21453 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1744928 T3346 C1223 P21453 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1744929 T3346 C1223 P21453 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1744930 T3346 C1223 P21453 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1744947 T3292 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1744948 T3292 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:21453__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:21453_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:21453"}
[junit4:junit4] 2> 1744952 T3298 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> 1744952 T3360 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> 1744952 T3327 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> 1744952 T3311 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> 1744952 T3291 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> 1744952 T3343 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> 1745168 T3361 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1745176 T3361 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1745178 T3361 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1745183 T3361 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1745205 T3361 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1745205 T3361 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1370876432811/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4/
[junit4:junit4] 2> 1745205 T3361 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a0430b6
[junit4:junit4] 2> 1745206 T3361 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1745206 T3361 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4
[junit4:junit4] 2> 1745207 T3361 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4/index/
[junit4:junit4] 2> 1745207 T3361 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1745207 T3361 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4/index
[junit4:junit4] 2> 1745211 T3361 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@878319f lockFactory=org.apache.lucene.store.NativeFSLockFactory@e483045),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1745211 T3361 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1745214 T3361 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1745214 T3361 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1745215 T3361 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1745215 T3361 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1745216 T3361 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1745216 T3361 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1745217 T3361 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1745218 T3361 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1745218 T3361 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1745228 T3361 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1745234 T3361 oass.SolrIndexSearcher.<init> Opening Searcher@c598c77 main
[junit4:junit4] 2> 1745235 T3361 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4/tlog
[junit4:junit4] 2> 1745236 T3361 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1745236 T3361 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1745240 T3364 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@c598c77 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1745242 T3361 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1745243 T3361 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:26447 collection:collection1 shard:shard2
[junit4:junit4] 2> 1745246 T3361 oasc.ZkController.register We are http://127.0.0.1:26447/collection1/ and leader is http://127.0.0.1:18032/collection1/
[junit4:junit4] 2> 1745246 T3361 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:26447
[junit4:junit4] 2> 1745246 T3361 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1745246 T3361 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1225 name=collection1 org.apache.solr.core.SolrCore@6de88f7f url=http://127.0.0.1:26447/collection1 node=127.0.0.1:26447_ C1225_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:26447_, base_url=http://127.0.0.1:26447}
[junit4:junit4] 2> 1745247 T3365 C1225 P26447 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1745247 T3365 C1225 P26447 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1745247 T3361 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1745247 T3365 C1225 P26447 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1745248 T3365 C1225 P26447 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1745248 T3269 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1745249 T3269 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1745249 T3365 C1225 P26447 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1745250 T3269 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1745273 T3269 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1745274 T3317 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:26447__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1745275 T3269 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 1745275 T3269 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 1745276 T3269 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1746278 T3269 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1746456 T3292 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1746457 T3292 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:26447__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:26447_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:26447"}
[junit4:junit4] 2> 1746477 T3298 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> 1746477 T3327 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> 1746477 T3291 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> 1746477 T3360 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> 1746477 T3343 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> 1746477 T3311 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> 1747277 T3317 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:26447__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1747277 T3317 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:26447__collection1&state=recovering&nodeName=127.0.0.1:26447_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 1747280 T3269 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1748282 T3269 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C1225_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:26447_, base_url=http://127.0.0.1:26447}
[junit4:junit4] 2> 1749279 T3365 C1225 P26447 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:18032/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1749279 T3365 C1225 P26447 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:26447 START replicas=[http://127.0.0.1:18032/collection1/] nUpdates=100
[junit4:junit4] 2> 1749280 T3365 C1225 P26447 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1749280 T3365 C1225 P26447 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1749280 T3365 C1225 P26447 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1749280 T3365 C1225 P26447 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1749281 T3365 C1225 P26447 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1749281 T3365 C1225 P26447 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:18032/collection1/. core=collection1
[junit4:junit4] 2> 1749281 T3365 C1225 P26447 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1749284 T3269 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C1226 name=collection1 org.apache.solr.core.SolrCore@7bea523f url=http://127.0.0.1:18032/collection1 node=127.0.0.1:18032_ C1226_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:18032_, base_url=http://127.0.0.1:18032, leader=true}
[junit4:junit4] 2> 1749288 T3318 C1226 P18032 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=0
[junit4:junit4] 2> 1749292 T3319 C1226 P18032 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1749294 T3319 C1226 P18032 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2263b473 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5bf259cd),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1749295 T3319 C1226 P18032 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1749296 T3319 C1226 P18032 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2263b473 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5bf259cd),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2263b473 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5bf259cd),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1749296 T3319 C1226 P18032 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1749296 T3319 C1226 P18032 oass.SolrIndexSearcher.<init> Opening Searcher@67b69ac8 realtime
[junit4:junit4] 2> 1749297 T3319 C1226 P18032 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1749297 T3319 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 1749298 T3365 C1225 P26447 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1749298 T3365 C1225 P26447 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1749300 T3320 C1226 P18032 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1749300 T3320 C1226 P18032 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 1749301 T3365 C1225 P26447 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1749301 T3365 C1225 P26447 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1749301 T3365 C1225 P26447 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1749303 T3320 C1226 P18032 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> 1749304 T3365 C1225 P26447 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1749305 T3365 C1225 P26447 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4/index.20130610170040237
[junit4:junit4] 2> 1749305 T3365 C1225 P26447 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1ddcbbf0 lockFactory=org.apache.lucene.store.NativeFSLockFactory@d80f54c) fullCopy=false
[junit4:junit4] 2> 1749307 T3320 C1226 P18032 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> 1749308 T3365 C1225 P26447 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1749309 T3365 C1225 P26447 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1749309 T3365 C1225 P26447 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1749311 T3365 C1225 P26447 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@878319f lockFactory=org.apache.lucene.store.NativeFSLockFactory@e483045),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@878319f lockFactory=org.apache.lucene.store.NativeFSLockFactory@e483045),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1749311 T3365 C1225 P26447 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1749311 T3365 C1225 P26447 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1749312 T3365 C1225 P26447 oass.SolrIndexSearcher.<init> Opening Searcher@7db44b0 main
[junit4:junit4] 2> 1749313 T3364 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7db44b0 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1749313 T3365 C1225 P26447 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4/index.20130610170040237 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4/index.20130610170040237;done=true>>]
[junit4:junit4] 2> 1749313 T3365 C1225 P26447 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4/index.20130610170040237
[junit4:junit4] 2> 1749314 T3365 C1225 P26447 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4/index.20130610170040237
[junit4:junit4] 2> 1749314 T3365 C1225 P26447 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1749314 T3365 C1225 P26447 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1749314 T3365 C1225 P26447 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1749314 T3365 C1225 P26447 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1749316 T3365 C1225 P26447 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1749492 T3292 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1749493 T3292 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:26447__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:26447_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:26447"}
[junit4:junit4] 2> 1749505 T3298 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> 1749505 T3343 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> 1749505 T3291 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> 1749505 T3311 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> 1749505 T3360 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> 1749505 T3327 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> 1750286 T3269 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1750287 T3269 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C1227 name=collection1 org.apache.solr.core.SolrCore@74c497e2 url=http://127.0.0.1:15284/collection1 node=127.0.0.1:15284_ C1227_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:15284_, base_url=http://127.0.0.1:15284, leader=true}
[junit4:junit4] 2> 1750295 T3281 C1227 P15284 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1750298 T3281 C1227 P15284 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3ca5e96 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e2e2c88),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1750299 T3281 C1227 P15284 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1750300 T3281 C1227 P15284 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3ca5e96 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e2e2c88),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3ca5e96 lockFactory=org.apache.lucene.store.NativeFSLockFactory@e2e2c88),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1750300 T3281 C1227 P15284 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1750301 T3281 C1227 P15284 oass.SolrIndexSearcher.<init> Opening Searcher@3ddabc06 main
[junit4:junit4] 2> 1750301 T3281 C1227 P15284 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1750302 T3295 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3ddabc06 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1750302 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 7
[junit4:junit4] 2> 1750312 T3321 C1226 P18032 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1750313 T3321 C1226 P18032 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2263b473 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5bf259cd),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2263b473 lockFactory=org.apache.lucene.store.NativeFSLockFactory@5bf259cd),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1750314 T3321 C1226 P18032 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1750314 T3321 C1226 P18032 oass.SolrIndexSearcher.<init> Opening Searcher@7ac9fe main
[junit4:junit4] 2> 1750315 T3321 C1226 P18032 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1750315 T3329 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7ac9fe main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1750316 T3321 C1226 P18032 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:57102/collection1/, StdNode: http://127.0.0.1:21453/collection1/, StdNode: http://127.0.0.1:26447/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> ASYNC NEW_CORE C1228 name=collection1 org.apache.solr.core.SolrCore@5a8f61f url=http://127.0.0.1:57102/collection1 node=127.0.0.1:57102_ C1228_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:57102_, base_url=http://127.0.0.1:57102, leader=true}
[junit4:junit4] 2> 1750319 T3305 C1228 P57102 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1750320 T3305 C1228 P57102 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7f4069c lockFactory=org.apache.lucene.store.NativeFSLockFactory@71d0d8cf),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7f4069c lockFactory=org.apache.lucene.store.NativeFSLockFactory@71d0d8cf),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1750320 T3305 C1228 P57102 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1750321 T3305 C1228 P57102 oass.SolrIndexSearcher.<init> Opening Searcher@407ba54a main
[junit4:junit4] 2> 1750321 T3305 C1228 P57102 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1750322 T3313 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@407ba54a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1750322 T3305 C1228 P57102 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 3
[junit4:junit4] 2> ASYNC NEW_CORE C1229 name=collection1 org.apache.solr.core.SolrCore@3857d30f url=http://127.0.0.1:21453/collection1 node=127.0.0.1:21453_ C1229_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:21453_, base_url=http://127.0.0.1:21453}
[junit4:junit4] 2> 1750326 T3333 C1229 P21453 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C1225_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:26447_, base_url=http://127.0.0.1:26447}
[junit4:junit4] 2> 1750327 T3350 C1225 P26447 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1750327 T3333 C1229 P21453 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7a39c335 lockFactory=org.apache.lucene.store.NativeFSLockFactory@315bc9f7),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7a39c335 lockFactory=org.apache.lucene.store.NativeFSLockFactory@315bc9f7),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1750328 T3350 C1225 P26447 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@878319f lockFactory=org.apache.lucene.store.NativeFSLockFactory@e483045),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@878319f lockFactory=org.apache.lucene.store.NativeFSLockFactory@e483045),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1750328 T3333 C1229 P21453 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1750329 T3350 C1225 P26447 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1750329 T3333 C1229 P21453 oass.SolrIndexSearcher.<init> Opening Searcher@6284d81e main
[junit4:junit4] 2> 1750330 T3350 C1225 P26447 oass.SolrIndexSearcher.<init> Opening Searcher@6e0fbeb8 main
[junit4:junit4] 2> 1750330 T3333 C1229 P21453 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1750331 T3345 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6284d81e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1750330 T3350 C1225 P26447 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1750331 T3333 C1229 P21453 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> 1750331 T3364 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6e0fbeb8 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1750332 T3350 C1225 P26447 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 6
[junit4:junit4] 2> 1750333 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 21
[junit4:junit4] 2> 1750334 T3269 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1750336 T3306 C1228 P57102 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> 1750339 T3334 C1229 P21453 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> 1750340 T3322 C1226 P18032 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> 1750342 T3351 C1225 P26447 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> 1752348 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437468137388769280)} 0 2
[junit4:junit4] 2> 1752357 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1437468137392963584&update.from=http://127.0.0.1:18032/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437468137392963584)} 0 2
[junit4:junit4] 2> 1752360 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1437468137397157888&update.from=http://127.0.0.1:57102/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437468137397157888)} 0 1
[junit4:junit4] 2> 1752361 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1437468137397157888)} 0 6
[junit4:junit4] 2> 1752361 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437468137392963584)} 0 10
[junit4:junit4] 2> 1752372 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1437468137406595072)]} 0 8
[junit4:junit4] 2> 1752378 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1437468137417080832)]} 0 1
[junit4:junit4] 2> 1752378 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1437468137417080832)]} 0 4
[junit4:junit4] 2> 1752382 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1437468137424420864)]} 0 1
[junit4:junit4] 2> 1752389 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1437468137429663744)]} 0 0
[junit4:junit4] 2> 1752390 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1437468137429663744)]} 0 4
[junit4:junit4] 2> 1752391 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1]} 0 7
[junit4:junit4] 2> 1752393 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1437468137437003776)]} 0 0
[junit4:junit4] 2> 1752400 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1437468137440149504)]} 0 1
[junit4:junit4] 2> 1752400 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1437468137440149504)]} 0 4
[junit4:junit4] 2> 1752404 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1437468137447489536)]} 0 1
[junit4:junit4] 2> 1752412 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1437468137452732416)]} 0 1
[junit4:junit4] 2> 1752413 T3323 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[3 (1437468137452732416)]} 0 5
[junit4:junit4] 2> 1752413 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3]} 0 7
[junit4:junit4] 2> 1752417 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1437468137461121024)]} 0 1
[junit4:junit4] 2> 1752427 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1437468137468461056)]} 0 1
[junit4:junit4] 2> 1752427 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[4 (1437468137468461056)]} 0 4
[junit4:junit4] 2> 1752428 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4]} 0 8
[junit4:junit4] 2> 1752430 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1437468137475801088)]} 0 0
[junit4:junit4] 2> 1752438 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1437468137481043968)]} 0 0
[junit4:junit4] 2> 1752439 T3323 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[5 (1437468137481043968)]} 0 4
[junit4:junit4] 2> 1752440 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5]} 0 7
[junit4:junit4] 2> 1752442 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1437468137488384000)]} 0 0
[junit4:junit4] 2> 1752448 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1437468137491529728)]} 0 0
[junit4:junit4] 2> 1752449 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1437468137491529728)]} 0 4
[junit4:junit4] 2> 1752452 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1437468137498869760)]} 0 0
[junit4:junit4] 2> 1752458 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1437468137502015488)]} 0 0
[junit4:junit4] 2> 1752459 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1437468137502015488)]} 0 4
[junit4:junit4] 2> 1752462 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1437468137509355520)]} 0 0
[junit4:junit4] 2> 1752470 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1437468137514598400)]} 0 0
[junit4:junit4] 2> 1752471 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1437468137514598400)]} 0 4
[junit4:junit4] 2> 1752472 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8]} 0 7
[junit4:junit4] 2> 1752474 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1437468137521938432)]} 0 0
[junit4:junit4] 2> 1752481 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1437468137525084160)]} 0 1
[junit4:junit4] 2> 1752481 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1437468137525084160)]} 0 4
[junit4:junit4] 2> 1752484 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1437468137532424192)]} 0 0
[junit4:junit4] 2> 1752493 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1437468137537667072)]} 0 1
[junit4:junit4] 2> 1752493 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[10 (1437468137537667072)]} 0 4
[junit4:junit4] 2> 1752494 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10]} 0 7
[junit4:junit4] 2> 1752496 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1437468137545007104)]} 0 0
[junit4:junit4] 2> 1752503 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1437468137548152832)]} 0 1
[junit4:junit4] 2> 1752503 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1437468137548152832)]} 0 4
[junit4:junit4] 2> 1752506 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1437468137555492864)]} 0 0
[junit4:junit4] 2> 1752512 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1437468137558638592)]} 0 0
[junit4:junit4] 2> 1752513 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1437468137558638592)]} 0 4
[junit4:junit4] 2> 1752516 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1437468137565978624)]} 0 0
[junit4:junit4] 2> 1752524 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1437468137571221504)]} 0 0
[junit4:junit4] 2> 1752525 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[13 (1437468137571221504)]} 0 4
[junit4:junit4] 2> 1752526 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13]} 0 7
[junit4:junit4] 2> 1752529 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1437468137578561536)]} 0 1
[junit4:junit4] 2> 1752537 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1437468137583804416)]} 0 1
[junit4:junit4] 2> 1752537 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[14 (1437468137583804416)]} 0 4
[junit4:junit4] 2> 1752538 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14]} 0 7
[junit4:junit4] 2> 1752548 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1437468137591144448)]} 0 8
[junit4:junit4] 2> 1752556 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1437468137604775936)]} 0 0
[junit4:junit4] 2> 1752557 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[15 (1437468137604775936)]} 0 4
[junit4:junit4] 2> 1752558 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15]} 0 7
[junit4:junit4] 2> 1752560 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1437468137612115968)]} 0 0
[junit4:junit4] 2> 1752568 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1437468137617358848)]} 0 0
[junit4:junit4] 2> 1752569 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[16 (1437468137617358848)]} 0 4
[junit4:junit4] 2> 1752570 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16]} 0 7
[junit4:junit4] 2> 1752572 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1437468137624698880)]} 0 0
[junit4:junit4] 2> 1752581 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1437468137629941760)]} 0 1
[junit4:junit4] 2> 1752581 T3323 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[17 (1437468137629941760)]} 0 4
[junit4:junit4] 2> 1752582 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17]} 0 7
[junit4:junit4] 2> 1752584 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1437468137637281792)]} 0 0
[junit4:junit4] 2> 1752593 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1437468137642524672)]} 0 1
[junit4:junit4] 2> 1752593 T3323 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[18 (1437468137642524672)]} 0 4
[junit4:junit4] 2> 1752594 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18]} 0 7
[junit4:junit4] 2> 1752596 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1437468137649864704)]} 0 0
[junit4:junit4] 2> 1752602 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1437468137653010432)]} 0 0
[junit4:junit4] 2> 1752603 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1437468137653010432)]} 0 4
[junit4:junit4] 2> 1752606 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1437468137660350464)]} 0 0
[junit4:junit4] 2> 1752614 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1437468137665593344)]} 0 0
[junit4:junit4] 2> 1752615 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[20 (1437468137665593344)]} 0 4
[junit4:junit4] 2> 1752616 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20]} 0 7
[junit4:junit4] 2> 1752619 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1437468137672933376)]} 0 1
[junit4:junit4] 2> 1752625 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1437468137676079104)]} 0 0
[junit4:junit4] 2> 1752625 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1437468137676079104)]} 0 4
[junit4:junit4] 2> 1752628 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1437468137683419136)]} 0 0
[junit4:junit4] 2> 1752637 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1437468137688662016)]} 0 1
[junit4:junit4] 2> 1752637 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[22 (1437468137688662016)]} 0 4
[junit4:junit4] 2> 1752638 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22]} 0 7
[junit4:junit4] 2> 1752640 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1437468137696002048)]} 0 0
[junit4:junit4] 2> 1752646 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1437468137699147776)]} 0 0
[junit4:junit4] 2> 1752647 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1437468137699147776)]} 0 4
[junit4:junit4] 2> 1752650 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1437468137706487808)]} 0 0
[junit4:junit4] 2> 1752657 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1437468137709633536)]} 0 1
[junit4:junit4] 2> 1752657 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1437468137709633536)]} 0 4
[junit4:junit4] 2> 1752660 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1437468137716973568)]} 0 0
[junit4:junit4] 2> 1752667 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1437468137720119296)]} 0 0
[junit4:junit4] 2> 1752667 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1437468137720119296)]} 0 4
[junit4:junit4] 2> 1752670 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1437468137727459328)]} 0 0
[junit4:junit4] 2> 1752677 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1437468137730605056)]} 0 0
[junit4:junit4] 2> 1752677 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1437468137730605056)]} 0 4
[junit4:junit4] 2> 1752680 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1437468137737945088)]} 0 0
[junit4:junit4] 2> 1752688 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1437468137743187968)]} 0 0
[junit4:junit4] 2> 1752689 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[27 (1437468137743187968)]} 0 4
[junit4:junit4] 2> 1752690 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27]} 0 7
[junit4:junit4] 2> 1752692 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1437468137750528000)]} 0 0
[junit4:junit4] 2> 1752699 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1437468137753673728)]} 0 1
[junit4:junit4] 2> 1752700 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1437468137753673728)]} 0 5
[junit4:junit4] 2> 1752702 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1437468137761013760)]} 0 0
[junit4:junit4] 2> 1752710 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1437468137766256640)]} 0 0
[junit4:junit4] 2> 1752711 T3323 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[29 (1437468137766256640)]} 0 4
[junit4:junit4] 2> 1752712 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29]} 0 7
[junit4:junit4] 2> 1752715 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1437468137773596672)]} 0 1
[junit4:junit4] 2> 1752723 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1437468137779888128)]} 0 0
[junit4:junit4] 2> 1752724 T3323 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[30 (1437468137779888128)]} 0 4
[junit4:junit4] 2> 1752725 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30]} 0 7
[junit4:junit4] 2> 1752727 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1437468137787228160)]} 0 0
[junit4:junit4] 2> 1752734 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1437468137790373888)]} 0 1
[junit4:junit4] 2> 1752735 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1437468137790373888)]} 0 5
[junit4:junit4] 2> 1752737 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1437468137797713920)]} 0 0
[junit4:junit4] 2> 1752743 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1437468137800859648)]} 0 0
[junit4:junit4] 2> 1752744 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1437468137800859648)]} 0 4
[junit4:junit4] 2> 1752747 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1437468137808199680)]} 0 0
[junit4:junit4] 2> 1752753 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1437468137811345408)]} 0 0
[junit4:junit4] 2> 1752754 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1437468137811345408)]} 0 4
[junit4:junit4] 2> 1752757 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1437468137818685440)]} 0 0
[junit4:junit4] 2> 1752763 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1437468137821831168)]} 0 0
[junit4:junit4] 2> 1752764 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1437468137821831168)]} 0 4
[junit4:junit4] 2> 1752767 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1437468137829171200)]} 0 0
[junit4:junit4] 2> 1752776 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1437468137835462656)]} 0 0
[junit4:junit4] 2> 1752777 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[35 (1437468137835462656)]} 0 4
[junit4:junit4] 2> 1752778 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35]} 0 8
[junit4:junit4] 2> 1752780 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1437468137842802688)]} 0 0
[junit4:junit4] 2> 1752788 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1437468137848045568)]} 0 0
[junit4:junit4] 2> 1752789 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[36 (1437468137848045568)]} 0 4
[junit4:junit4] 2> 1752790 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36]} 0 7
[junit4:junit4] 2> 1752792 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1437468137855385600)]} 0 0
[junit4:junit4] 2> 1752798 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1437468137858531328)]} 0 0
[junit4:junit4] 2> 1752799 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1437468137858531328)]} 0 4
[junit4:junit4] 2> 1752802 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1437468137865871360)]} 0 0
[junit4:junit4] 2> 1752810 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1437468137871114240)]} 0 0
[junit4:junit4] 2> 1752811 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[38 (1437468137871114240)]} 0 4
[junit4:junit4] 2> 1752812 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38]} 0 7
[junit4:junit4] 2> 1752814 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1437468137878454272)]} 0 0
[junit4:junit4] 2> 1752821 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1437468137881600000)]} 0 1
[junit4:junit4] 2> 1752821 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1437468137881600000)]} 0 4
[junit4:junit4] 2> 1752824 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1437468137888940032)]} 0 0
[junit4:junit4] 2> 1752830 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1437468137892085760)]} 0 0
[junit4:junit4] 2> 1752831 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1437468137892085760)]} 0 4
[junit4:junit4] 2> 1752834 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1437468137899425792)]} 0 0
[junit4:junit4] 2> 1752843 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1437468137905717248)]} 0 0
[junit4:junit4] 2> 1752844 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[41 (1437468137905717248)]} 0 4
[junit4:junit4] 2> 1752845 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41]} 0 8
[junit4:junit4] 2> 1752848 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1437468137913057280)]} 0 1
[junit4:junit4] 2> 1752857 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1437468137920397312)]} 0 0
[junit4:junit4] 2> 1752858 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[42 (1437468137920397312)]} 0 4
[junit4:junit4] 2> 1752859 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42]} 0 8
[junit4:junit4] 2> 1752861 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1437468137927737344)]} 0 0
[junit4:junit4] 2> 1752867 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1437468137930883072)]} 0 0
[junit4:junit4] 2> 1752868 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1437468137930883072)]} 0 4
[junit4:junit4] 2> 1752871 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1437468137938223104)]} 0 0
[junit4:junit4] 2> 1752877 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1437468137941368832)]} 0 0
[junit4:junit4] 2> 1752878 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1437468137941368832)]} 0 4
[junit4:junit4] 2> 1752882 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1437468137948708864)]} 0 1
[junit4:junit4] 2> 1752890 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1437468137955000320)]} 0 0
[junit4:junit4] 2> 1752891 T3323 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[45 (1437468137955000320)]} 0 4
[junit4:junit4] 2> 1752892 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45]} 0 7
[junit4:junit4] 2> 1752894 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1437468137962340352)]} 0 0
[junit4:junit4] 2> 1752901 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1437468137965486080)]} 0 1
[junit4:junit4] 2> 1752901 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1437468137965486080)]} 0 4
[junit4:junit4] 2> 1752904 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1437468137972826112)]} 0 0
[junit4:junit4] 2> 1752914 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1437468137979117568)]} 0 1
[junit4:junit4] 2> 1752914 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[47 (1437468137979117568)]} 0 4
[junit4:junit4] 2> 1752915 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47]} 0 8
[junit4:junit4] 2> 1752919 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1437468137987506176)]} 0 1
[junit4:junit4] 2> 1752927 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1437468137992749056)]} 0 1
[junit4:junit4] 2> 1752927 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[48 (1437468137992749056)]} 0 4
[junit4:junit4] 2> 1752928 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48]} 0 7
[junit4:junit4] 2> 1752932 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1437468138001137664)]} 0 1
[junit4:junit4] 2> 1752940 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1437468138006380544)]} 0 1
[junit4:junit4] 2> 1752940 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[49 (1437468138006380544)]} 0 4
[junit4:junit4] 2> 1752941 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49]} 0 7
[junit4:junit4] 2> 1752945 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1437468138014769152)]} 0 1
[junit4:junit4] 2> 1752951 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1437468138017914880)]} 0 1
[junit4:junit4] 2> 1752952 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1437468138017914880)]} 0 5
[junit4:junit4] 2> 1752956 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1437468138026303488)]} 0 1
[junit4:junit4] 2> 1752962 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1437468138029449216)]} 0 1
[junit4:junit4] 2> 1752962 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1437468138029449216)]} 0 4
[junit4:junit4] 2> 1752966 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1437468138036789248)]} 0 1
[junit4:junit4] 2> 1752972 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1437468138039934976)]} 0 1
[junit4:junit4] 2> 1752972 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1437468138039934976)]} 0 4
[junit4:junit4] 2> 1752976 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1437468138047275008)]} 0 1
[junit4:junit4] 2> 1752985 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1437468138053566464)]} 0 1
[junit4:junit4] 2> 1752985 T3323 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[53 (1437468138053566464)]} 0 4
[junit4:junit4] 2> 1752986 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53]} 0 8
[junit4:junit4] 2> 1752989 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1437468138061955072)]} 0 0
[junit4:junit4] 2> 1752995 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1437468138065100800)]} 0 0
[junit4:junit4] 2> 1752996 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1437468138065100800)]} 0 4
[junit4:junit4] 2> 1752999 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1437468138072440832)]} 0 0
[junit4:junit4] 2> 1753006 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1437468138075586560)]} 0 1
[junit4:junit4] 2> 1753006 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1437468138075586560)]} 0 4
[junit4:junit4] 2> 1753010 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1437468138082926592)]} 0 1
[junit4:junit4] 2> 1753015 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1437468138086072320)]} 0 0
[junit4:junit4] 2> 1753016 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1437468138086072320)]} 0 4
[junit4:junit4] 2> 1753020 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1437468138093412352)]} 0 1
[junit4:junit4] 2> 1753027 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1437468138097606656)]} 0 0
[junit4:junit4] 2> 1753027 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1437468138097606656)]} 0 4
[junit4:junit4] 2> 1753031 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1437468138104946688)]} 0 1
[junit4:junit4] 2> 1753038 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1437468138109140992)]} 0 1
[junit4:junit4] 2> 1753038 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1437468138109140992)]} 0 4
[junit4:junit4] 2> 1753041 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1437468138116481024)]} 0 0
[junit4:junit4] 2> 1753048 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1437468138119626752)]} 0 1
[junit4:junit4] 2> 1753048 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1437468138119626752)]} 0 4
[junit4:junit4] 2> 1753052 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1437468138126966784)]} 0 1
[junit4:junit4] 2> 1753060 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1437468138133258240)]} 0 0
[junit4:junit4] 2> 1753061 T3323 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[60 (1437468138133258240)]} 0 4
[junit4:junit4] 2> 1753062 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60]} 0 7
[junit4:junit4] 2> 1753065 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1437468138140598272)]} 0 1
[junit4:junit4] 2> 1753071 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1437468138144792576)]} 0 0
[junit4:junit4] 2> 1753072 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1437468138144792576)]} 0 4
[junit4:junit4] 2> 1753076 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1437468138152132608)]} 0 1
[junit4:junit4] 2> 1753083 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[62 (1437468138156326912)]} 0 0
[junit4:junit4] 2> 1753083 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1437468138156326912)]} 0 4
[junit4:junit4] 2> 1753087 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1437468138163666944)]} 0 1
[junit4:junit4] 2> 1753092 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[63 (1437468138166812672)]} 0 0
[junit4:junit4] 2> 1753093 T3307 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1437468138166812672)]} 0 4
[junit4:junit4] 2> 1753096 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1437468138174152704)]} 0 0
[junit4:junit4] 2> 1753105 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[64 (1437468138179395584)]} 0 1
[junit4:junit4] 2> 1753106 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[64 (1437468138179395584)]} 0 5
[junit4:junit4] 2> 1753106 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64]} 0 7
[junit4:junit4] 2> 1753110 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1437468138187784192)]} 0 1
[junit4:junit4] 2> 1753118 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[65 (1437468138193027072)]} 0 1
[junit4:junit4] 2> 1753118 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[65 (1437468138193027072)]} 0 4
[junit4:junit4] 2> 1753119 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65]} 0 7
[junit4:junit4] 2> 1753122 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1437468138201415680)]} 0 0
[junit4:junit4] 2> 1753131 T3335 C1229 P21453 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:57102/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[66 (1437468138206658560)]} 0 1
[junit4:junit4] 2> 1753131 T3305 C1228 P57102 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[66 (1437468138206658560)]} 0 4
[junit4:junit4] 2> 1753132 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66]} 0 7
[junit4:junit4] 2> 1753136 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1437468138215047168)]} 0 1
[junit4:junit4] 2> 1753142 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[67 (1437468138218192896)]} 0 1
[junit4:junit4] 2> 1753142 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1437468138218192896)]} 0 4
[junit4:junit4] 2> 1753146 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1437468138225532928)]} 0 1
[junit4:junit4] 2> 1753152 T3350 C1225 P26447 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:18032/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[68 (1437468138228678656)]} 0 1
[junit4:junit4] 2> 1753153 T3321 C1226 P18032 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1437468138228678656)]} 0 5
[junit4:junit4] 2> 1753155 T3281 C1227 P15284 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={w
[...truncated too long message...]
012338 T3360 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 2012341 T3360 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 2012341 T3360 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 2012341 T3360 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4;done=false>>]
[junit4:junit4] 2> 2012342 T3360 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4
[junit4:junit4] 2> 2012342 T3360 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4/index;done=false>>]
[junit4:junit4] 2> 2012342 T3360 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1370876415216/jetty4/index
[junit4:junit4] 2> 2012342 T3360 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 2012342 T3360 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election/89841756748120076-127.0.0.1:26447__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> 2012343 T3360 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> 2012343 T3360 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2012343 T3360 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2012343 T3360 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> 2012343 T3360 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2012344 T3360 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=FastDecompressionCompressingStoredFields(storedFieldsFormat=CompressingStoredFieldsFormat(compressionMode=FAST_DECOMPRESSION, chunkSize=270), termVectorsFormat=CompressingTermVectorsFormat(compressionMode=FAST_DECOMPRESSION, chunkSize=270)), sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=hr_HR, timezone=Europe/Vaduz
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=3,free=309902816,total=509935616
[junit4:junit4] 2> NOTE: All tests run in this JVM: [DateFieldTest, MBeansHandlerTest, SolrTestCaseJ4Test, LukeRequestHandlerTest, TermsComponentTest, SOLR749Test, TestPluginEnable, TestMaxScoreQueryParser, StatelessScriptUpdateProcessorFactoryTest, TestSurroundQueryParser, TestFastWriter, PluginInfoTest, CSVRequestHandlerTest, OverseerCollectionProcessorTest, SliceStateTest, SuggesterTest, TestFaceting, TestLMDirichletSimilarityFactory, DirectUpdateHandlerOptimizeTest, TestConfig, FieldMutatingUpdateProcessorTest, CacheHeaderTest, QueryResultKeyTest, ZkCLITest, TestSchemaResource, TestFuzzyAnalyzedSuggestions, BadCopyFieldTest, TestSweetSpotSimilarityFactory, ExternalFileFieldSortTest, DocValuesTest, TestRealTimeGet, TestLFUCache, BasicDistributedZkTest, BasicFunctionalityTest, TestStressVersions, TestCoreContainer, TestFieldCollectionResource, UnloadDistributedZkTest, TestReloadAndDeleteDocs, DistributedSpellCheckComponentTest, TestSolrDeletionPolicy2, AutoCommitTest, TestUniqueKeyFieldResource, TestPseudoReturnFields, TestJoin, TestSearchPerf, TestReversedWildcardFilterFactory, AliasIntegrationTest, SuggesterFSTTest, TestDocumentBuilder, DocumentBuilderTest, TestTrie, TestLRUCache, TestQuerySenderListener, SolrCoreTest, ZkControllerTest, JsonLoaderTest, SliceStateUpdateTest, SchemaVersionSpecificBehaviorTest, DistributedTermsComponentTest, AlternateDirectoryTest, SpellingQueryConverterTest, IndexSchemaTest, QueryParsingTest, BinaryUpdateRequestHandlerTest, PrimitiveFieldTypeTest, TestCloudManagedSchemaAddField, TestSolrCoreProperties, TestExtendedDismaxParser, ResourceLoaderTest, PolyFieldTest, UpdateRequestProcessorFactoryTest, BasicDistributedZk2Test, SyncSliceTest, ClusterStateUpdateTest, TestRandomDVFaceting, SimpleFacetsTest, TestSolr4Spatial, TestGroupingSearch, TestBadConfig, HighlighterTest, ShowFileRequestHandlerTest, CurrencyFieldOpenExchangeTest, DistributedQueryElevationComponentTest, SolrIndexSplitterTest, AnalysisAfterCoreReloadTest, TestFoldingMultitermQuery, SuggesterTSTTest, SuggesterWFSTTest, WordBreakSolrSpellCheckerTest, QueryEqualityTest, DefaultValueUpdateProcessorTest, TestRemoteStreaming, DistanceFunctionTest, TestSolrDeletionPolicy1, IndexBasedSpellCheckerTest, TestQueryUtils, TestWriterPerf, TestOmitPositions, XmlUpdateRequestHandlerTest, TermVectorComponentTest, RequiredFieldsTest, FieldAnalysisRequestHandlerTest, TestArbitraryIndexDir, LoggingHandlerTest, SolrPluginUtilsTest, JSONWriterTest, TestPartialUpdateDeduplication, SearchHandlerTest, TestBinaryResponseWriter, TestPropInjectDefaults, UpdateParamsTest, ResponseLogComponentTest, BadComponentTest, TestStressRecovery, DateMathParserTest, PreAnalyzedFieldTest, SystemInfoHandlerTest, CircularListTest, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J0 in 288.54s, 1 test, 1 error <<< FAILURES!
[...truncated 10 lines...]
BUILD FAILED
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:391: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:371: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/build.xml:39: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build.xml:181: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/common-build.xml:437: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:1243: The following error occurred while executing this line:
/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/lucene/common-build.xml:887: There were test failures: 297 suites, 1246 tests, 1 error, 13 ignored (7 assumptions)
Total time: 53 minutes 8 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure