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/13 06:07:50 UTC
[JENKINS] Lucene-Solr-Tests-4.x-Java6 - Build # 1705 - Failure
Build: https://builds.apache.org/job/Lucene-Solr-Tests-4.x-Java6/1705/
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:26734 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:26734 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([AEDC281926B1E192:2F3AA60151EE81AE]: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 9575 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 1825132 T3925 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 1825137 T3925 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./solrtest-ChaosMonkeyShardSplitTest-1371096118256
[junit4:junit4] 2> 1825139 T3925 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1825140 T3926 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1825241 T3925 oasc.ZkTestServer.run start zk server on port:55750
[junit4:junit4] 2> 1825242 T3925 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1825248 T3932 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1155780e name:ZooKeeperConnection Watcher:127.0.0.1:55750 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1825248 T3925 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1825249 T3925 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1825265 T3925 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1825267 T3934 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@eddc5c8 name:ZooKeeperConnection Watcher:127.0.0.1:55750/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1825267 T3925 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1825268 T3925 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1825272 T3925 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1825276 T3925 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1825279 T3925 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1825288 T3925 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> 1825289 T3925 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1825302 T3925 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> 1825303 T3925 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1825408 T3925 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> 1825409 T3925 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1825412 T3925 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> 1825412 T3925 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1825415 T3925 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> 1825416 T3925 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1825419 T3925 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> 1825419 T3925 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1825422 T3925 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> 1825422 T3925 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1825425 T3925 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> 1825426 T3925 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1825428 T3925 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> 1825429 T3925 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1825625 T3925 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1825629 T3925 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:60390
[junit4:junit4] 2> 1825629 T3925 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1825630 T3925 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1825630 T3925 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371096118550
[junit4:junit4] 2> 1825630 T3925 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371096118550/solr.xml
[junit4:junit4] 2> 1825631 T3925 oasc.CoreContainer.<init> New CoreContainer 1941336786
[junit4:junit4] 2> 1825631 T3925 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371096118550/'
[junit4:junit4] 2> 1825631 T3925 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371096118550/'
[junit4:junit4] 2> 1825705 T3925 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1825706 T3925 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1825706 T3925 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1825706 T3925 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1825707 T3925 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1825707 T3925 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1825707 T3925 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1825708 T3925 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1825708 T3925 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1825708 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1825719 T3925 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1825719 T3925 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55750/solr
[junit4:junit4] 2> 1825720 T3925 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1825721 T3925 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1825723 T3945 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6f8a245c name:ZooKeeperConnection Watcher:127.0.0.1:55750 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1825723 T3925 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1825726 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1825732 T3925 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1825734 T3947 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@6fb9fa84 name:ZooKeeperConnection Watcher:127.0.0.1:55750/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1825734 T3925 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1825736 T3925 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1825739 T3925 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1825742 T3925 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1825744 T3925 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:60390_
[junit4:junit4] 2> 1825752 T3925 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:60390_
[junit4:junit4] 2> 1825754 T3925 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1825770 T3925 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1825777 T3925 oasc.Overseer.start Overseer (id=89856155206680579-127.0.0.1:60390_-n_0000000000) starting
[junit4:junit4] 2> 1825781 T3925 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1825794 T3949 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1825796 T3925 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1825798 T3925 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1825799 T3925 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1825801 T3948 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1825804 T3950 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1825804 T3950 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1827304 T3948 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1827305 T3948 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:60390_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60390"}
[junit4:junit4] 2> 1827305 T3948 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1827305 T3948 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1827347 T3947 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> 1827807 T3950 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371096118550/collection1
[junit4:junit4] 2> 1827807 T3950 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1827808 T3950 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1827808 T3950 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1827810 T3950 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371096118550/collection1/'
[junit4:junit4] 2> 1827811 T3950 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371096118550/collection1/lib/README' to classloader
[junit4:junit4] 2> 1827812 T3950 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371096118550/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1827870 T3950 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1827936 T3950 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1828039 T3950 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1828047 T3950 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1828480 T3950 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1828483 T3950 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1828485 T3950 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1828488 T3950 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1828507 T3950 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1828507 T3950 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371096118550/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/control/data/
[junit4:junit4] 2> 1828507 T3950 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@74e16785
[junit4:junit4] 2> 1828508 T3950 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1828508 T3950 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/control/data
[junit4:junit4] 2> 1828509 T3950 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/control/data/index/
[junit4:junit4] 2> 1828509 T3950 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1828509 T3950 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/control/data/index
[junit4:junit4] 2> 1828512 T3950 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2092a7f5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2de8b64d),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1828512 T3950 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1828515 T3950 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1828515 T3950 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1828516 T3950 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1828516 T3950 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1828516 T3950 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1828517 T3950 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1828517 T3950 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1828517 T3950 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1828517 T3950 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1828527 T3950 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1828534 T3950 oass.SolrIndexSearcher.<init> Opening Searcher@3bce8d8e main
[junit4:junit4] 2> 1828534 T3950 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/control/data/tlog
[junit4:junit4] 2> 1828535 T3950 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1828536 T3950 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1828539 T3951 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@3bce8d8e main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1828540 T3950 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1828540 T3950 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:60390 collection:control_collection shard:shard1
[junit4:junit4] 2> 1828541 T3950 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1828561 T3950 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1828570 T3950 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1828570 T3950 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1828571 T3950 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:60390/collection1/
[junit4:junit4] 2> 1828571 T3950 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1828571 T3950 oasc.SyncStrategy.syncToMe http://127.0.0.1:60390/collection1/ has no replicas
[junit4:junit4] 2> 1828571 T3950 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:60390/collection1/
[junit4:junit4] 2> 1828571 T3950 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1828851 T3948 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1828870 T3947 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> 1828895 T3950 oasc.ZkController.register We are http://127.0.0.1:60390/collection1/ and leader is http://127.0.0.1:60390/collection1/
[junit4:junit4] 2> 1828895 T3950 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:60390
[junit4:junit4] 2> 1828895 T3950 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1828895 T3950 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1828895 T3950 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1828897 T3950 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1828898 T3925 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 1828899 T3925 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1828899 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1828911 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1828912 T3925 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1828914 T3954 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4d76857b name:ZooKeeperConnection Watcher:127.0.0.1:55750/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1828915 T3925 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1828917 T3925 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1828918 T3925 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1829153 T3925 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1829156 T3925 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:26734
[junit4:junit4] 2> 1829156 T3925 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1829157 T3925 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1829157 T3925 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371096122037
[junit4:junit4] 2> 1829157 T3925 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371096122037/solr.xml
[junit4:junit4] 2> 1829158 T3925 oasc.CoreContainer.<init> New CoreContainer 797020745
[junit4:junit4] 2> 1829158 T3925 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371096122037/'
[junit4:junit4] 2> 1829158 T3925 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371096122037/'
[junit4:junit4] 2> 1829231 T3925 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1829232 T3925 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1829232 T3925 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1829233 T3925 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1829233 T3925 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1829233 T3925 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1829234 T3925 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1829234 T3925 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1829234 T3925 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1829235 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1829245 T3925 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1829246 T3925 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55750/solr
[junit4:junit4] 2> 1829246 T3925 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1829247 T3925 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1829249 T3965 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7364f582 name:ZooKeeperConnection Watcher:127.0.0.1:55750 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1829250 T3925 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1829252 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1829260 T3925 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1829261 T3967 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5bfc3dd9 name:ZooKeeperConnection Watcher:127.0.0.1:55750/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1829262 T3925 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1829273 T3925 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1830276 T3925 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:26734_
[junit4:junit4] 2> 1830278 T3925 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:26734_
[junit4:junit4] 2> 1830281 T3947 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1830281 T3967 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1830281 T3954 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1830282 T3947 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> 1830293 T3968 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1830294 T3968 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1830383 T3948 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1830384 T3948 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:60390_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:60390"}
[junit4:junit4] 2> 1830386 T3948 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:26734_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:26734"}
[junit4:junit4] 2> 1830387 T3948 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 1830387 T3948 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1830399 T3947 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> 1830399 T3954 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> 1830399 T3967 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> 1831296 T3968 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371096122037/collection1
[junit4:junit4] 2> 1831296 T3968 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1831297 T3968 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1831297 T3968 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1831298 T3968 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371096122037/collection1/'
[junit4:junit4] 2> 1831299 T3968 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371096122037/collection1/lib/README' to classloader
[junit4:junit4] 2> 1831300 T3968 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371096122037/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1831347 T3968 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1831391 T3968 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1831493 T3968 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1831498 T3968 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1831880 T3968 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1831882 T3968 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1831884 T3968 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1831888 T3968 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1831905 T3968 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1831905 T3968 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371096122037/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty1/
[junit4:junit4] 2> 1831905 T3968 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@74e16785
[junit4:junit4] 2> 1831906 T3968 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1831906 T3968 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty1
[junit4:junit4] 2> 1831907 T3968 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty1/index/
[junit4:junit4] 2> 1831907 T3968 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1831908 T3968 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty1/index
[junit4:junit4] 2> 1831911 T3968 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5b369d81 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f4107bb),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1831911 T3968 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1831913 T3968 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1831913 T3968 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1831914 T3968 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1831914 T3968 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1831915 T3968 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1831915 T3968 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1831915 T3968 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1831916 T3968 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1831916 T3968 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1831922 T3968 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1831927 T3968 oass.SolrIndexSearcher.<init> Opening Searcher@784df874 main
[junit4:junit4] 2> 1831927 T3968 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty1/tlog
[junit4:junit4] 2> 1831928 T3968 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1831928 T3968 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1831931 T3969 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@784df874 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1831933 T3968 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1831933 T3968 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:26734 collection:collection1 shard:shard1
[junit4:junit4] 2> 1831934 T3968 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 1831941 T3968 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1831952 T3968 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1831952 T3968 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1831952 T3968 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:26734/collection1/
[junit4:junit4] 2> 1831952 T3968 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1831952 T3968 oasc.SyncStrategy.syncToMe http://127.0.0.1:26734/collection1/ has no replicas
[junit4:junit4] 2> 1831952 T3968 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:26734/collection1/
[junit4:junit4] 2> 1831953 T3968 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1833414 T3948 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1833428 T3947 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> 1833429 T3954 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> 1833429 T3967 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> 1833447 T3968 oasc.ZkController.register We are http://127.0.0.1:26734/collection1/ and leader is http://127.0.0.1:26734/collection1/
[junit4:junit4] 2> 1833447 T3968 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:26734
[junit4:junit4] 2> 1833447 T3968 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1833447 T3968 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1833448 T3968 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1833449 T3968 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1833450 T3925 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 1833451 T3925 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1833452 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1833727 T3925 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1833731 T3925 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:26312
[junit4:junit4] 2> 1833732 T3925 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1833732 T3925 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1833733 T3925 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371096126586
[junit4:junit4] 2> 1833733 T3925 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371096126586/solr.xml
[junit4:junit4] 2> 1833734 T3925 oasc.CoreContainer.<init> New CoreContainer 106182006
[junit4:junit4] 2> 1833734 T3925 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371096126586/'
[junit4:junit4] 2> 1833735 T3925 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371096126586/'
[junit4:junit4] 2> 1833845 T3925 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1833845 T3925 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1833846 T3925 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1833846 T3925 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1833847 T3925 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1833847 T3925 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1833848 T3925 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1833848 T3925 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1833849 T3925 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1833849 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1833864 T3925 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1833865 T3925 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55750/solr
[junit4:junit4] 2> 1833865 T3925 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1833867 T3925 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1833869 T3981 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1adc2e78 name:ZooKeeperConnection Watcher:127.0.0.1:55750 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1833870 T3925 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1833873 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1833882 T3925 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1833884 T3983 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@5397b7f9 name:ZooKeeperConnection Watcher:127.0.0.1:55750/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1833885 T3925 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1833890 T3925 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1834894 T3925 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:26312_
[junit4:junit4] 2> 1834896 T3925 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:26312_
[junit4:junit4] 2> 1834900 T3967 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> 1834900 T3954 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> 1834900 T3983 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1834900 T3947 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1834901 T3947 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> 1834901 T3967 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1834902 T3954 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1834907 T3984 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1834907 T3984 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1834934 T3948 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1834935 T3948 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"2",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:26734_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:26734"}
[junit4:junit4] 2> 1834938 T3948 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:26312_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:26312"}
[junit4:junit4] 2> 1834939 T3948 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1834939 T3948 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1834956 T3983 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> 1834956 T3947 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> 1834956 T3954 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> 1834956 T3967 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> 1835911 T3984 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371096126586/collection1
[junit4:junit4] 2> 1835911 T3984 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1835912 T3984 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1835912 T3984 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1835914 T3984 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371096126586/collection1/'
[junit4:junit4] 2> 1835915 T3984 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371096126586/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1835916 T3984 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371096126586/collection1/lib/README' to classloader
[junit4:junit4] 2> 1835967 T3984 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1836025 T3984 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1836127 T3984 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1836135 T3984 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1836702 T3984 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1836706 T3984 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1836708 T3984 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1836713 T3984 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1836735 T3984 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1836735 T3984 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371096126586/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty2/
[junit4:junit4] 2> 1836735 T3984 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@74e16785
[junit4:junit4] 2> 1836736 T3984 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1836736 T3984 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty2
[junit4:junit4] 2> 1836737 T3984 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty2/index/
[junit4:junit4] 2> 1836737 T3984 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1836739 T3984 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty2/index
[junit4:junit4] 2> 1836742 T3984 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@543ddf5c lockFactory=org.apache.lucene.store.NativeFSLockFactory@64ef6eb8),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1836743 T3984 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1836746 T3984 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1836746 T3984 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1836747 T3984 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1836747 T3984 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1836748 T3984 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1836748 T3984 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1836749 T3984 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1836749 T3984 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1836750 T3984 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1836759 T3984 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1836766 T3984 oass.SolrIndexSearcher.<init> Opening Searcher@2d0835be main
[junit4:junit4] 2> 1836767 T3984 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty2/tlog
[junit4:junit4] 2> 1836768 T3984 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1836768 T3984 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1836773 T3985 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@2d0835be main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1836775 T3984 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1836775 T3984 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:26312 collection:collection1 shard:shard2
[junit4:junit4] 2> 1836776 T3984 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 1836800 T3984 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1836811 T3984 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1836811 T3984 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1836812 T3984 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:26312/collection1/
[junit4:junit4] 2> 1836812 T3984 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1836812 T3984 oasc.SyncStrategy.syncToMe http://127.0.0.1:26312/collection1/ has no replicas
[junit4:junit4] 2> 1836812 T3984 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:26312/collection1/
[junit4:junit4] 2> 1836813 T3984 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1837964 T3948 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1838006 T3983 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> 1838006 T3954 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> 1838006 T3967 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> 1838006 T3947 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> 1838056 T3984 oasc.ZkController.register We are http://127.0.0.1:26312/collection1/ and leader is http://127.0.0.1:26312/collection1/
[junit4:junit4] 2> 1838056 T3984 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:26312
[junit4:junit4] 2> 1838056 T3984 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1838056 T3984 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1838057 T3984 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1838059 T3984 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1838060 T3925 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 1838060 T3925 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1838061 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1838434 T3925 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1838438 T3925 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:24221
[junit4:junit4] 2> 1838439 T3925 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1838439 T3925 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1838440 T3925 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371096131197
[junit4:junit4] 2> 1838440 T3925 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371096131197/solr.xml
[junit4:junit4] 2> 1838441 T3925 oasc.CoreContainer.<init> New CoreContainer 2030985071
[junit4:junit4] 2> 1838442 T3925 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371096131197/'
[junit4:junit4] 2> 1838442 T3925 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371096131197/'
[junit4:junit4] 2> 1838581 T3925 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1838582 T3925 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1838582 T3925 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1838583 T3925 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1838583 T3925 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1838584 T3925 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1838584 T3925 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1838585 T3925 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1838585 T3925 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1838586 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1838605 T3925 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1838606 T3925 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55750/solr
[junit4:junit4] 2> 1838606 T3925 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1838608 T3925 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1838610 T3997 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@7c4fdc57 name:ZooKeeperConnection Watcher:127.0.0.1:55750 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1838611 T3925 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1838614 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1838628 T3925 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1838631 T3999 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12122416 name:ZooKeeperConnection Watcher:127.0.0.1:55750/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1838632 T3925 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1838650 T3925 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1839514 T3948 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1839515 T3948 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"3",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:26312_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:26312"}
[junit4:junit4] 2> 1839520 T3983 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> 1839520 T3947 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> 1839520 T3954 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> 1839520 T3967 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> 1839520 T3999 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> 1839653 T3925 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:24221_
[junit4:junit4] 2> 1839655 T3925 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:24221_
[junit4:junit4] 2> 1839657 T3999 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> 1839657 T3983 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> 1839657 T3967 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> 1839657 T3954 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> 1839657 T3947 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1839658 T3947 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> 1839659 T3999 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1839659 T3983 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1839659 T3967 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1839670 T3954 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1839674 T4000 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1839675 T4000 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1841032 T3948 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1841033 T3948 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:24221_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:24221"}
[junit4:junit4] 2> 1841034 T3948 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1841034 T3948 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1841049 T3983 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> 1841049 T3999 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> 1841049 T3954 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> 1841049 T3967 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> 1841049 T3947 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> 1841678 T4000 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371096131197/collection1
[junit4:junit4] 2> 1841678 T4000 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1841679 T4000 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1841679 T4000 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1841681 T4000 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371096131197/collection1/'
[junit4:junit4] 2> 1841683 T4000 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371096131197/collection1/lib/README' to classloader
[junit4:junit4] 2> 1841684 T4000 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371096131197/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1841746 T4000 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1841816 T4000 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1841918 T4000 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1841926 T4000 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1842656 T4000 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1842660 T4000 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1842663 T4000 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1842772 T4000 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1842794 T4000 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1842794 T4000 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371096131197/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty3/
[junit4:junit4] 2> 1842794 T4000 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@74e16785
[junit4:junit4] 2> 1842795 T4000 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1842796 T4000 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty3
[junit4:junit4] 2> 1842796 T4000 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty3/index/
[junit4:junit4] 2> 1842796 T4000 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1842797 T4000 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty3/index
[junit4:junit4] 2> 1842801 T4000 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7bcd8263 lockFactory=org.apache.lucene.store.NativeFSLockFactory@371ed2b4),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1842802 T4000 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1842805 T4000 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1842805 T4000 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1842806 T4000 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1842806 T4000 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1842807 T4000 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1842807 T4000 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1842808 T4000 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1842808 T4000 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1842809 T4000 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1842822 T4000 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1842831 T4000 oass.SolrIndexSearcher.<init> Opening Searcher@4128c71a main
[junit4:junit4] 2> 1842831 T4000 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty3/tlog
[junit4:junit4] 2> 1842833 T4000 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1842833 T4000 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1842838 T4001 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4128c71a main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1842840 T4000 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1842840 T4000 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:24221 collection:collection1 shard:shard1
[junit4:junit4] 2> 1842843 T4000 oasc.ZkController.register We are http://127.0.0.1:24221/collection1/ and leader is http://127.0.0.1:26734/collection1/
[junit4:junit4] 2> 1842843 T4000 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:24221
[junit4:junit4] 2> 1842844 T4000 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1842844 T4000 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2017 name=collection1 org.apache.solr.core.SolrCore@3992a907 url=http://127.0.0.1:24221/collection1 node=127.0.0.1:24221_ C2017_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:24221_, base_url=http://127.0.0.1:24221}
[junit4:junit4] 2> 1842844 T4002 C2017 P24221 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1842845 T4002 C2017 P24221 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1842845 T4000 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1842845 T4002 C2017 P24221 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1842845 T4002 C2017 P24221 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1842846 T3925 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 1842847 T4002 C2017 P24221 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1842847 T3925 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1842848 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1842873 T3957 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1843192 T3925 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1843195 T3925 oejs.AbstractConnector.doStart Started SocketConnector@127.0.0.1:40144
[junit4:junit4] 2> 1843196 T3925 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1843197 T3925 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1843197 T3925 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371096135990
[junit4:junit4] 2> 1843198 T3925 oasc.CoreContainer$Initializer.initialize looking for solr config file: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371096135990/solr.xml
[junit4:junit4] 2> 1843198 T3925 oasc.CoreContainer.<init> New CoreContainer 246943020
[junit4:junit4] 2> 1843199 T3925 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371096135990/'
[junit4:junit4] 2> 1843199 T3925 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371096135990/'
[junit4:junit4] 2> 1843337 T3925 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1843338 T3925 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1843339 T3925 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1843339 T3925 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1843340 T3925 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1843340 T3925 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1843341 T3925 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1843341 T3925 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1843342 T3925 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1843342 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1843361 T3925 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1843362 T3925 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:55750/solr
[junit4:junit4] 2> 1843363 T3925 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1843364 T3925 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1843366 T4014 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@52f8028e name:ZooKeeperConnection Watcher:127.0.0.1:55750 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1843367 T3925 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1843370 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1843382 T3925 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1843384 T4016 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@37e80b39 name:ZooKeeperConnection Watcher:127.0.0.1:55750/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1843384 T3925 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1843395 T3925 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1844056 T3948 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1844057 T3948 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:24221_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:24221"}
[junit4:junit4] 2> 1844072 T3983 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> 1844072 T3954 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> 1844072 T3999 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> 1844072 T3947 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> 1844072 T3967 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> 1844072 T4016 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> 1844400 T3925 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40144_
[junit4:junit4] 2> 1844403 T3925 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40144_
[junit4:junit4] 2> 1844406 T3983 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> 1844406 T3954 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> 1844406 T3999 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> 1844406 T3967 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> 1844406 T3947 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1844406 T4016 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1844407 T3947 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> 1844408 T3983 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1844408 T4016 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> 1844414 T3954 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1844414 T3999 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1844415 T3967 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1844420 T4017 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1844420 T4017 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1844876 T3957 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 4, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1844876 T3957 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=4&state=recovering&nodeName=127.0.0.1:24221_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2003
[junit4:junit4] 2> 1845577 T3948 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1845578 T3948 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:40144_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40144"}
[junit4:junit4] 2> 1845578 T3948 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1845579 T3948 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1845594 T3983 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> 1845594 T3954 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> 1845594 T3999 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> 1845594 T4016 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> 1845594 T3947 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> 1845594 T3967 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> 1846424 T4017 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371096135990/collection1
[junit4:junit4] 2> 1846424 T4017 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1846425 T4017 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1846425 T4017 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1846428 T4017 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371096135990/collection1/'
[junit4:junit4] 2> 1846430 T4017 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371096135990/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1846431 T4017 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371096135990/collection1/lib/README' to classloader
[junit4:junit4] 2> 1846494 T4017 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 1846562 T4017 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1846665 T4017 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1846673 T4017 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C2018 name=collection1 org.apache.solr.core.SolrCore@3992a907 url=http://127.0.0.1:24221/collection1 node=127.0.0.1:24221_ C2018_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:24221_, base_url=http://127.0.0.1:24221}
[junit4:junit4] 2> 1846878 T4002 C2018 P24221 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:26734/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1846878 T4002 C2018 P24221 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:24221 START replicas=[http://127.0.0.1:26734/collection1/] nUpdates=100
[junit4:junit4] 2> 1846879 T4002 C2018 P24221 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1846879 T4002 C2018 P24221 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1846879 T4002 C2018 P24221 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1846879 T4002 C2018 P24221 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1846880 T4002 C2018 P24221 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1846880 T4002 C2018 P24221 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:26734/collection1/. core=collection1
[junit4:junit4] 2> 1846880 T4002 C2018 P24221 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C2019 name=collection1 org.apache.solr.core.SolrCore@b8fb27c url=http://127.0.0.1:26734/collection1 node=127.0.0.1:26734_ C2019_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:26734_, base_url=http://127.0.0.1:26734, leader=true}
[junit4:junit4] 2> 1846888 T3958 C2019 P26734 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> 1846891 T3959 C2019 P26734 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1846945 T3959 C2019 P26734 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5b369d81 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f4107bb),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1846946 T3959 C2019 P26734 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1846946 T3959 C2019 P26734 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5b369d81 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f4107bb),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5b369d81 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f4107bb),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1846947 T3959 C2019 P26734 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1846947 T3959 C2019 P26734 oass.SolrIndexSearcher.<init> Opening Searcher@65892d78 realtime
[junit4:junit4] 2> 1846948 T3959 C2019 P26734 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1846948 T3959 C2019 P26734 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 57
[junit4:junit4] 2> 1846949 T4002 C2018 P24221 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1846949 T4002 C2018 P24221 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1846951 T3960 C2019 P26734 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1846952 T3960 C2019 P26734 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 1846952 T4002 C2018 P24221 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1846953 T4002 C2018 P24221 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1846953 T4002 C2018 P24221 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1846955 T3960 C2019 P26734 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> 1846956 T4002 C2018 P24221 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1846957 T4002 C2018 P24221 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty3/index.20130612190220074
[junit4:junit4] 2> 1846958 T4002 C2018 P24221 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@7b15c40c lockFactory=org.apache.lucene.store.NativeFSLockFactory@76c03089) fullCopy=false
[junit4:junit4] 2> 1846960 T3960 C2019 P26734 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> 1846961 T4002 C2018 P24221 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1846961 T4002 C2018 P24221 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1846962 T4002 C2018 P24221 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1846964 T4002 C2018 P24221 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7bcd8263 lockFactory=org.apache.lucene.store.NativeFSLockFactory@371ed2b4),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7bcd8263 lockFactory=org.apache.lucene.store.NativeFSLockFactory@371ed2b4),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1846964 T4002 C2018 P24221 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1846964 T4002 C2018 P24221 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1846965 T4002 C2018 P24221 oass.SolrIndexSearcher.<init> Opening Searcher@32f6adf6 main
[junit4:junit4] 2> 1846966 T4001 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@32f6adf6 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1846966 T4002 C2018 P24221 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty3/index.20130612190220074 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty3/index.20130612190220074;done=true>>]
[junit4:junit4] 2> 1846966 T4002 C2018 P24221 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty3/index.20130612190220074
[junit4:junit4] 2> 1846967 T4002 C2018 P24221 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty3/index.20130612190220074
[junit4:junit4] 2> 1846967 T4002 C2018 P24221 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1846967 T4002 C2018 P24221 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1846967 T4002 C2018 P24221 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1846967 T4002 C2018 P24221 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1846969 T4002 C2018 P24221 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1847099 T3948 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1847100 T3948 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"4",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:24221_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:24221"}
[junit4:junit4] 2> 1847135 T3983 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> 1847135 T3954 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> 1847135 T3999 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> 1847135 T3967 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> 1847135 T3947 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> 1847135 T4016 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> 1847368 T4017 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1847373 T4017 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1847375 T4017 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1847381 T4017 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1847402 T4017 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1847402 T4017 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371096135990/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4/
[junit4:junit4] 2> 1847402 T4017 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@74e16785
[junit4:junit4] 2> 1847403 T4017 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1847404 T4017 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4
[junit4:junit4] 2> 1847404 T4017 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4/index/
[junit4:junit4] 2> 1847404 T4017 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1847405 T4017 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4/index
[junit4:junit4] 2> 1847410 T4017 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@54cf83a2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@693ac240),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1847410 T4017 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1847414 T4017 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1847414 T4017 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1847415 T4017 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1847415 T4017 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1847416 T4017 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1847416 T4017 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1847417 T4017 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1847418 T4017 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1847418 T4017 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1847431 T4017 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1847441 T4017 oass.SolrIndexSearcher.<init> Opening Searcher@540516fa main
[junit4:junit4] 2> 1847442 T4017 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4/tlog
[junit4:junit4] 2> 1847443 T4017 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1847443 T4017 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1847448 T4020 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@540516fa main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1847450 T4017 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1847450 T4017 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40144 collection:collection1 shard:shard2
[junit4:junit4] 2> 1847453 T4017 oasc.ZkController.register We are http://127.0.0.1:40144/collection1/ and leader is http://127.0.0.1:26312/collection1/
[junit4:junit4] 2> 1847454 T4017 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40144
[junit4:junit4] 2> 1847454 T4017 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1847454 T4017 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C2020 name=collection1 org.apache.solr.core.SolrCore@431972e4 url=http://127.0.0.1:40144/collection1 node=127.0.0.1:40144_ C2020_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:40144_, base_url=http://127.0.0.1:40144}
[junit4:junit4] 2> 1847455 T4021 C2020 P40144 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1847455 T4021 C2020 P40144 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1847455 T4017 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1847455 T4021 C2020 P40144 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1847455 T4021 C2020 P40144 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1847456 T3925 oass.SolrDispatchFilter.init user.dir=/usr/home/hudson/hudson-slave/workspace/Lucene-Solr-Tests-4.x-Java6/solr/build/solr-core/test/J1
[junit4:junit4] 2> 1847457 T4021 C2020 P40144 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1847457 T3925 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1847458 T3925 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1847478 T3925 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1847479 T3973 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1847479 T3925 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 1847480 T3925 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 1847481 T3925 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1848483 T3925 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1848640 T3948 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1848641 T3948 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:40144_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40144"}
[junit4:junit4] 2> 1848663 T3983 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> 1848663 T3999 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> 1848663 T4016 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> 1848663 T3947 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> 1848663 T3954 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> 1848663 T3967 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> 1849483 T3973 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 5, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1849483 T3973 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=5&state=recovering&nodeName=127.0.0.1:40144_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2004
[junit4:junit4] 2> 1849485 T3925 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1850488 T3925 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C2020_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:40144_, base_url=http://127.0.0.1:40144}
[junit4:junit4] 2> 1851486 T4021 C2020 P40144 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:26312/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1851486 T4021 C2020 P40144 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40144 START replicas=[http://127.0.0.1:26312/collection1/] nUpdates=100
[junit4:junit4] 2> 1851487 T4021 C2020 P40144 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1851487 T4021 C2020 P40144 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1851487 T4021 C2020 P40144 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1851487 T4021 C2020 P40144 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1851487 T4021 C2020 P40144 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1851488 T4021 C2020 P40144 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:26312/collection1/. core=collection1
[junit4:junit4] 2> 1851489 T4021 C2020 P40144 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1851491 T3925 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C2021 name=collection1 org.apache.solr.core.SolrCore@1a34fef9 url=http://127.0.0.1:26312/collection1 node=127.0.0.1:26312_ C2021_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:26312_, base_url=http://127.0.0.1:26312, leader=true}
[junit4:junit4] 2> 1851496 T3974 C2021 P26312 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> 1851506 T3975 C2021 P26312 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1851558 T3975 C2021 P26312 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@543ddf5c lockFactory=org.apache.lucene.store.NativeFSLockFactory@64ef6eb8),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1851559 T3975 C2021 P26312 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1851559 T3975 C2021 P26312 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@543ddf5c lockFactory=org.apache.lucene.store.NativeFSLockFactory@64ef6eb8),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@543ddf5c lockFactory=org.apache.lucene.store.NativeFSLockFactory@64ef6eb8),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1851560 T3975 C2021 P26312 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1851560 T3975 C2021 P26312 oass.SolrIndexSearcher.<init> Opening Searcher@4ba4eb85 realtime
[junit4:junit4] 2> 1851561 T3975 C2021 P26312 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1851561 T3975 C2021 P26312 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 56
[junit4:junit4] 2> 1851562 T4021 C2020 P40144 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1851562 T4021 C2020 P40144 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1851563 T3976 C2021 P26312 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1851564 T3976 C2021 P26312 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=1
[junit4:junit4] 2> 1851564 T4021 C2020 P40144 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1851565 T4021 C2020 P40144 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1851565 T4021 C2020 P40144 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1851568 T3976 C2021 P26312 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> 1851569 T4021 C2020 P40144 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1851572 T4021 C2020 P40144 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4/index.20130612190224688
[junit4:junit4] 2> 1851572 T4021 C2020 P40144 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@2b156273 lockFactory=org.apache.lucene.store.NativeFSLockFactory@4089412) fullCopy=false
[junit4:junit4] 2> 1851576 T3976 C2021 P26312 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> 1851577 T4021 C2020 P40144 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1851578 T4021 C2020 P40144 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1851578 T4021 C2020 P40144 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1851579 T4021 C2020 P40144 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@54cf83a2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@693ac240),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@54cf83a2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@693ac240),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1851580 T4021 C2020 P40144 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1851580 T4021 C2020 P40144 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1851580 T4021 C2020 P40144 oass.SolrIndexSearcher.<init> Opening Searcher@10fe4748 main
[junit4:junit4] 2> 1851581 T4020 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@10fe4748 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1851582 T4021 C2020 P40144 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4/index.20130612190224688 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4/index.20130612190224688;done=true>>]
[junit4:junit4] 2> 1851582 T4021 C2020 P40144 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4/index.20130612190224688
[junit4:junit4] 2> 1851583 T4021 C2020 P40144 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4/index.20130612190224688
[junit4:junit4] 2> 1851583 T4021 C2020 P40144 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1851583 T4021 C2020 P40144 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1851583 T4021 C2020 P40144 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1851583 T4021 C2020 P40144 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1851585 T4021 C2020 P40144 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1851670 T3948 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1851671 T3948 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"5",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:40144_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40144"}
[junit4:junit4] 2> 1851689 T3967 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> 1851690 T3999 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> 1851689 T3954 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> 1851689 T3947 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> 1851689 T3983 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> 1851689 T4016 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> 1852493 T3925 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1852495 T3925 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C2022 name=collection1 org.apache.solr.core.SolrCore@107156c2 url=http://127.0.0.1:60390/collection1 node=127.0.0.1:60390_ C2022_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:60390_, base_url=http://127.0.0.1:60390, leader=true}
[junit4:junit4] 2> 1852516 T3937 C2022 P60390 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1852570 T3937 C2022 P60390 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2092a7f5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2de8b64d),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1852571 T3937 C2022 P60390 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1852572 T3937 C2022 P60390 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2092a7f5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2de8b64d),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2092a7f5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@2de8b64d),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1852572 T3937 C2022 P60390 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1852573 T3937 C2022 P60390 oass.SolrIndexSearcher.<init> Opening Searcher@479abd4a main
[junit4:junit4] 2> 1852573 T3937 C2022 P60390 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1852574 T3951 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@479abd4a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1852575 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 59
[junit4:junit4] 2> 1852589 T3977 C2021 P26312 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1852592 T3977 C2021 P26312 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@543ddf5c lockFactory=org.apache.lucene.store.NativeFSLockFactory@64ef6eb8),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@543ddf5c lockFactory=org.apache.lucene.store.NativeFSLockFactory@64ef6eb8),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1852592 T3977 C2021 P26312 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1852593 T3977 C2021 P26312 oass.SolrIndexSearcher.<init> Opening Searcher@315f1f43 main
[junit4:junit4] 2> 1852593 T3977 C2021 P26312 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1852594 T3985 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@315f1f43 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1852594 T3977 C2021 P26312 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:26734/collection1/, StdNode: http://127.0.0.1:24221/collection1/, StdNode: http://127.0.0.1:40144/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> ASYNC NEW_CORE C2023 name=collection1 org.apache.solr.core.SolrCore@b8fb27c url=http://127.0.0.1:26734/collection1 node=127.0.0.1:26734_ C2023_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:26734_, base_url=http://127.0.0.1:26734, leader=true}
[junit4:junit4] 2> 1852597 T3961 C2023 P26734 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1852599 T3961 C2023 P26734 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5b369d81 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f4107bb),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@5b369d81 lockFactory=org.apache.lucene.store.NativeFSLockFactory@3f4107bb),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1852599 T3961 C2023 P26734 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1852600 T3961 C2023 P26734 oass.SolrIndexSearcher.<init> Opening Searcher@733743ae main
[junit4:junit4] 2> 1852600 T3961 C2023 P26734 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1852601 T3969 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@733743ae main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1852602 T3961 C2023 P26734 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> C2020_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:40144_, base_url=http://127.0.0.1:40144}
[junit4:junit4] 2> 1852606 T4006 C2020 P40144 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> ASYNC NEW_CORE C2024 name=collection1 org.apache.solr.core.SolrCore@3992a907 url=http://127.0.0.1:24221/collection1 node=127.0.0.1:24221_ C2024_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:24221_, base_url=http://127.0.0.1:24221}
[junit4:junit4] 2> 1852607 T3989 C2024 P24221 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1852607 T4006 C2020 P40144 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@54cf83a2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@693ac240),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@54cf83a2 lockFactory=org.apache.lucene.store.NativeFSLockFactory@693ac240),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1852608 T3989 C2024 P24221 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7bcd8263 lockFactory=org.apache.lucene.store.NativeFSLockFactory@371ed2b4),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@7bcd8263 lockFactory=org.apache.lucene.store.NativeFSLockFactory@371ed2b4),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1852608 T4006 C2020 P40144 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1852609 T3989 C2024 P24221 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1852609 T4006 C2020 P40144 oass.SolrIndexSearcher.<init> Opening Searcher@4a1d4e43 main
[junit4:junit4] 2> 1852610 T3989 C2024 P24221 oass.SolrIndexSearcher.<init> Opening Searcher@f138ffb main
[junit4:junit4] 2> 1852610 T4006 C2020 P40144 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1852611 T4020 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4a1d4e43 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1852610 T3989 C2024 P24221 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1852611 T4006 C2020 P40144 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> 1852611 T4001 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@f138ffb main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1852612 T3989 C2024 P24221 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> 1852613 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 24
[junit4:junit4] 2> 1852614 T3925 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1852617 T3962 C2023 P26734 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> 1852619 T3990 C2024 P24221 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> 1852620 T3978 C2021 P26312 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> 1852622 T4007 C2020 P40144 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> 1854630 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437698514218909696)} 0 2
[junit4:junit4] 2> 1854638 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1437698514223104000&update.from=http://127.0.0.1:26734/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437698514223104000)} 0 2
[junit4:junit4] 2> 1854641 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1437698514227298304&update.from=http://127.0.0.1:26312/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1437698514227298304)} 0 1
[junit4:junit4] 2> 1854642 T3979 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1437698514227298304)} 0 6
[junit4:junit4] 2> 1854643 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1437698514223104000)} 0 11
[junit4:junit4] 2> 1854646 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1437698514237784064)]} 0 0
[junit4:junit4] 2> 1854653 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1437698514243026944)]} 0 0
[junit4:junit4] 2> 1854654 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1437698514243026944)]} 0 3
[junit4:junit4] 2> 1854655 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0]} 0 5
[junit4:junit4] 2> 1854657 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1437698514249318400)]} 0 0
[junit4:junit4] 2> 1854666 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1437698514256658432)]} 0 0
[junit4:junit4] 2> 1854667 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1437698514256658432)]} 0 3
[junit4:junit4] 2> 1854668 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1]} 0 7
[junit4:junit4] 2> 1854671 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1437698514263998464)]} 0 0
[junit4:junit4] 2> 1854676 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1437698514267144192)]} 0 0
[junit4:junit4] 2> 1854677 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1437698514267144192)]} 0 3
[junit4:junit4] 2> 1854681 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1437698514274484224)]} 0 0
[junit4:junit4] 2> 1854687 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1437698514278678528)]} 0 0
[junit4:junit4] 2> 1854688 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1437698514278678528)]} 0 3
[junit4:junit4] 2> 1854691 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1437698514284969984)]} 0 0
[junit4:junit4] 2> 1854698 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1437698514290212864)]} 0 0
[junit4:junit4] 2> 1854699 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[4 (1437698514290212864)]} 0 3
[junit4:junit4] 2> 1854699 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4]} 0 5
[junit4:junit4] 2> 1854702 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1437698514296504320)]} 0 0
[junit4:junit4] 2> 1854707 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1437698514299650048)]} 0 0
[junit4:junit4] 2> 1854708 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1437698514299650048)]} 0 3
[junit4:junit4] 2> 1854711 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1437698514305941504)]} 0 0
[junit4:junit4] 2> 1854719 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1437698514312232960)]} 0 0
[junit4:junit4] 2> 1854720 T3979 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[6 (1437698514312232960)]} 0 3
[junit4:junit4] 2> 1854720 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6]} 0 5
[junit4:junit4] 2> 1854724 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1437698514319572992)]} 0 0
[junit4:junit4] 2> 1854734 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1437698514326913024)]} 0 0
[junit4:junit4] 2> 1854735 T3979 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[7 (1437698514326913024)]} 0 4
[junit4:junit4] 2> 1854735 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7]} 0 7
[junit4:junit4] 2> 1854739 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1437698514335301632)]} 0 0
[junit4:junit4] 2> 1854749 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1437698514342641664)]} 0 0
[junit4:junit4] 2> 1854750 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1437698514342641664)]} 0 4
[junit4:junit4] 2> 1854750 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8]} 0 7
[junit4:junit4] 2> 1854753 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1437698514349981696)]} 0 0
[junit4:junit4] 2> 1854758 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1437698514353127424)]} 0 0
[junit4:junit4] 2> 1854759 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1437698514353127424)]} 0 3
[junit4:junit4] 2> 1854761 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1437698514358370304)]} 0 0
[junit4:junit4] 2> 1854768 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1437698514363613184)]} 0 0
[junit4:junit4] 2> 1854769 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[10 (1437698514363613184)]} 0 3
[junit4:junit4] 2> 1854769 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10]} 0 5
[junit4:junit4] 2> 1854772 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1437698514369904640)]} 0 0
[junit4:junit4] 2> 1854779 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1437698514375147520)]} 0 0
[junit4:junit4] 2> 1854780 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[11 (1437698514375147520)]} 0 3
[junit4:junit4] 2> 1854780 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11]} 0 5
[junit4:junit4] 2> 1854783 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1437698514381438976)]} 0 0
[junit4:junit4] 2> 1854790 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1437698514386681856)]} 0 0
[junit4:junit4] 2> 1854791 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[12 (1437698514386681856)]} 0 3
[junit4:junit4] 2> 1854791 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12]} 0 5
[junit4:junit4] 2> 1854794 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1437698514392973312)]} 0 0
[junit4:junit4] 2> 1854799 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1437698514396119040)]} 0 0
[junit4:junit4] 2> 1854800 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1437698514396119040)]} 0 3
[junit4:junit4] 2> 1854803 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1437698514402410496)]} 0 0
[junit4:junit4] 2> 1854810 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1437698514407653376)]} 0 0
[junit4:junit4] 2> 1854811 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[14 (1437698514407653376)]} 0 3
[junit4:junit4] 2> 1854811 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14]} 0 5
[junit4:junit4] 2> 1854814 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1437698514413944832)]} 0 0
[junit4:junit4] 2> 1854821 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1437698514419187712)]} 0 0
[junit4:junit4] 2> 1854822 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[15 (1437698514419187712)]} 0 3
[junit4:junit4] 2> 1854822 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15]} 0 5
[junit4:junit4] 2> 1854826 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1437698514426527744)]} 0 0
[junit4:junit4] 2> 1854831 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1437698514429673472)]} 0 0
[junit4:junit4] 2> 1854832 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1437698514429673472)]} 0 3
[junit4:junit4] 2> 1854834 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1437698514434916352)]} 0 0
[junit4:junit4] 2> 1854840 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1437698514439110656)]} 0 0
[junit4:junit4] 2> 1854841 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1437698514439110656)]} 0 3
[junit4:junit4] 2> 1854843 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1437698514444353536)]} 0 0
[junit4:junit4] 2> 1854849 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1437698514448547840)]} 0 0
[junit4:junit4] 2> 1854850 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1437698514448547840)]} 0 3
[junit4:junit4] 2> 1854852 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1437698514453790720)]} 0 0
[junit4:junit4] 2> 1854858 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1437698514456936448)]} 0 0
[junit4:junit4] 2> 1854859 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1437698514456936448)]} 0 4
[junit4:junit4] 2> 1854861 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1437698514463227904)]} 0 0
[junit4:junit4] 2> 1854869 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1437698514469519360)]} 0 0
[junit4:junit4] 2> 1854870 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[20 (1437698514469519360)]} 0 3
[junit4:junit4] 2> 1854870 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20]} 0 5
[junit4:junit4] 2> 1854873 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1437698514475810816)]} 0 0
[junit4:junit4] 2> 1854879 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1437698514480005120)]} 0 0
[junit4:junit4] 2> 1854880 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1437698514480005120)]} 0 3
[junit4:junit4] 2> 1854883 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1437698514486296576)]} 0 0
[junit4:junit4] 2> 1854891 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1437698514491539456)]} 0 0
[junit4:junit4] 2> 1854892 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[22 (1437698514491539456)]} 0 4
[junit4:junit4] 2> 1854893 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22]} 0 7
[junit4:junit4] 2> 1854895 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1437698514498879488)]} 0 0
[junit4:junit4] 2> 1854900 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1437698514502025216)]} 0 0
[junit4:junit4] 2> 1854901 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1437698514502025216)]} 0 3
[junit4:junit4] 2> 1854903 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1437698514507268096)]} 0 0
[junit4:junit4] 2> 1854908 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1437698514510413824)]} 0 0
[junit4:junit4] 2> 1854909 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1437698514510413824)]} 0 3
[junit4:junit4] 2> 1854911 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1437698514515656704)]} 0 0
[junit4:junit4] 2> 1854918 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1437698514520899584)]} 0 0
[junit4:junit4] 2> 1854919 T3979 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[25 (1437698514520899584)]} 0 3
[junit4:junit4] 2> 1854919 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25]} 0 5
[junit4:junit4] 2> 1854922 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1437698514527191040)]} 0 0
[junit4:junit4] 2> 1854927 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1437698514530336768)]} 0 0
[junit4:junit4] 2> 1854928 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1437698514530336768)]} 0 3
[junit4:junit4] 2> 1854930 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1437698514535579648)]} 0 0
[junit4:junit4] 2> 1854935 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1437698514538725376)]} 0 0
[junit4:junit4] 2> 1854936 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1437698514538725376)]} 0 3
[junit4:junit4] 2> 1854938 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1437698514543968256)]} 0 0
[junit4:junit4] 2> 1854945 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1437698514549211136)]} 0 0
[junit4:junit4] 2> 1854946 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[28 (1437698514549211136)]} 0 3
[junit4:junit4] 2> 1854946 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28]} 0 5
[junit4:junit4] 2> 1854949 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1437698514555502592)]} 0 0
[junit4:junit4] 2> 1854957 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1437698514560745472)]} 0 1
[junit4:junit4] 2> 1854958 T3979 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[29 (1437698514560745472)]} 0 4
[junit4:junit4] 2> 1854958 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29]} 0 6
[junit4:junit4] 2> 1854961 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1437698514568085504)]} 0 0
[junit4:junit4] 2> 1854967 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1437698514571231232)]} 0 0
[junit4:junit4] 2> 1854968 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1437698514571231232)]} 0 4
[junit4:junit4] 2> 1854971 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1437698514578571264)]} 0 0
[junit4:junit4] 2> 1854980 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1437698514585911296)]} 0 0
[junit4:junit4] 2> 1854981 T3979 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[31 (1437698514585911296)]} 0 3
[junit4:junit4] 2> 1854981 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31]} 0 6
[junit4:junit4] 2> 1854984 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1437698514592202752)]} 0 0
[junit4:junit4] 2> 1854989 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1437698514595348480)]} 0 0
[junit4:junit4] 2> 1854990 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1437698514595348480)]} 0 3
[junit4:junit4] 2> 1854993 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1437698514601639936)]} 0 0
[junit4:junit4] 2> 1854998 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1437698514604785664)]} 0 0
[junit4:junit4] 2> 1854999 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1437698514604785664)]} 0 3
[junit4:junit4] 2> 1855001 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1437698514610028544)]} 0 0
[junit4:junit4] 2> 1855007 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1437698514614222848)]} 0 0
[junit4:junit4] 2> 1855008 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1437698514614222848)]} 0 3
[junit4:junit4] 2> 1855011 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1437698514620514304)]} 0 0
[junit4:junit4] 2> 1855019 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1437698514626805760)]} 0 0
[junit4:junit4] 2> 1855020 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[35 (1437698514626805760)]} 0 3
[junit4:junit4] 2> 1855020 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35]} 0 6
[junit4:junit4] 2> 1855023 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1437698514633097216)]} 0 0
[junit4:junit4] 2> 1855029 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1437698514637291520)]} 0 0
[junit4:junit4] 2> 1855030 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1437698514637291520)]} 0 3
[junit4:junit4] 2> 1855033 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1437698514643582976)]} 0 0
[junit4:junit4] 2> 1855042 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1437698514650923008)]} 0 0
[junit4:junit4] 2> 1855043 T3979 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[37 (1437698514650923008)]} 0 3
[junit4:junit4] 2> 1855043 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37]} 0 6
[junit4:junit4] 2> 1855046 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1437698514657214464)]} 0 0
[junit4:junit4] 2> 1855053 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1437698514661408768)]} 0 0
[junit4:junit4] 2> 1855054 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1437698514661408768)]} 0 4
[junit4:junit4] 2> 1855056 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1437698514667700224)]} 0 0
[junit4:junit4] 2> 1855063 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1437698514671894528)]} 0 0
[junit4:junit4] 2> 1855064 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1437698514671894528)]} 0 4
[junit4:junit4] 2> 1855067 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1437698514679234560)]} 0 0
[junit4:junit4] 2> 1855076 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1437698514685526016)]} 0 0
[junit4:junit4] 2> 1855077 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[40 (1437698514685526016)]} 0 4
[junit4:junit4] 2> 1855078 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40]} 0 7
[junit4:junit4] 2> 1855080 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1437698514692866048)]} 0 0
[junit4:junit4] 2> 1855087 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1437698514697060352)]} 0 0
[junit4:junit4] 2> 1855088 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1437698514697060352)]} 0 4
[junit4:junit4] 2> 1855091 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1437698514704400384)]} 0 0
[junit4:junit4] 2> 1855098 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1437698514709643264)]} 0 0
[junit4:junit4] 2> 1855099 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[42 (1437698514709643264)]} 0 3
[junit4:junit4] 2> 1855099 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42]} 0 5
[junit4:junit4] 2> 1855103 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1437698514716983296)]} 0 0
[junit4:junit4] 2> 1855109 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1437698514721177600)]} 0 0
[junit4:junit4] 2> 1855110 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1437698514721177600)]} 0 3
[junit4:junit4] 2> 1855114 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1437698514728517632)]} 0 0
[junit4:junit4] 2> 1855121 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1437698514732711936)]} 0 0
[junit4:junit4] 2> 1855122 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1437698514732711936)]} 0 4
[junit4:junit4] 2> 1855126 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1437698514741100544)]} 0 0
[junit4:junit4] 2> 1855133 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1437698514745294848)]} 0 0
[junit4:junit4] 2> 1855134 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1437698514745294848)]} 0 4
[junit4:junit4] 2> 1855137 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1437698514752634880)]} 0 0
[junit4:junit4] 2> 1855146 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1437698514758926336)]} 0 0
[junit4:junit4] 2> 1855147 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[46 (1437698514758926336)]} 0 4
[junit4:junit4] 2> 1855148 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46]} 0 7
[junit4:junit4] 2> 1855151 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1437698514767314944)]} 0 0
[junit4:junit4] 2> 1855158 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1437698514772557824)]} 0 0
[junit4:junit4] 2> 1855159 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[47 (1437698514772557824)]} 0 3
[junit4:junit4] 2> 1855160 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47]} 0 6
[junit4:junit4] 2> 1855162 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1437698514778849280)]} 0 0
[junit4:junit4] 2> 1855167 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1437698514781995008)]} 0 0
[junit4:junit4] 2> 1855168 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1437698514781995008)]} 0 3
[junit4:junit4] 2> 1855170 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1437698514787237888)]} 0 0
[junit4:junit4] 2> 1855175 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1437698514790383616)]} 0 0
[junit4:junit4] 2> 1855176 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1437698514790383616)]} 0 3
[junit4:junit4] 2> 1855179 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1437698514796675072)]} 0 0
[junit4:junit4] 2> 1855185 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1437698514800869376)]} 0 0
[junit4:junit4] 2> 1855186 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1437698514800869376)]} 0 3
[junit4:junit4] 2> 1855188 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1437698514806112256)]} 0 0
[junit4:junit4] 2> 1855193 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1437698514809257984)]} 0 0
[junit4:junit4] 2> 1855194 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1437698514809257984)]} 0 3
[junit4:junit4] 2> 1855196 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1437698514814500864)]} 0 0
[junit4:junit4] 2> 1855203 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1437698514819743744)]} 0 0
[junit4:junit4] 2> 1855204 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[52 (1437698514819743744)]} 0 3
[junit4:junit4] 2> 1855204 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52]} 0 5
[junit4:junit4] 2> 1855207 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1437698514826035200)]} 0 0
[junit4:junit4] 2> 1855214 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1437698514831278080)]} 0 0
[junit4:junit4] 2> 1855215 T3979 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[53 (1437698514831278080)]} 0 3
[junit4:junit4] 2> 1855215 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53]} 0 5
[junit4:junit4] 2> 1855218 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1437698514837569536)]} 0 0
[junit4:junit4] 2> 1855224 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1437698514841763840)]} 0 0
[junit4:junit4] 2> 1855225 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1437698514841763840)]} 0 3
[junit4:junit4] 2> 1855227 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1437698514847006720)]} 0 0
[junit4:junit4] 2> 1855235 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1437698514852249600)]} 0 0
[junit4:junit4] 2> 1855236 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[55 (1437698514852249600)]} 0 4
[junit4:junit4] 2> 1855236 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55]} 0 6
[junit4:junit4] 2> 1855239 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1437698514859589632)]} 0 0
[junit4:junit4] 2> 1855246 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1437698514864832512)]} 0 0
[junit4:junit4] 2> 1855247 T3979 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[56 (1437698514864832512)]} 0 3
[junit4:junit4] 2> 1855247 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56]} 0 5
[junit4:junit4] 2> 1855250 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1437698514871123968)]} 0 0
[junit4:junit4] 2> 1855257 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1437698514876366848)]} 0 0
[junit4:junit4] 2> 1855258 T3979 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[57 (1437698514876366848)]} 0 3
[junit4:junit4] 2> 1855258 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57]} 0 5
[junit4:junit4] 2> 1855261 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1437698514882658304)]} 0 0
[junit4:junit4] 2> 1855269 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1437698514888949760)]} 0 0
[junit4:junit4] 2> 1855270 T3979 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[58 (1437698514888949760)]} 0 3
[junit4:junit4] 2> 1855270 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58]} 0 6
[junit4:junit4] 2> 1855273 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1437698514895241216)]} 0 0
[junit4:junit4] 2> 1855278 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1437698514898386944)]} 0 0
[junit4:junit4] 2> 1855279 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1437698514898386944)]} 0 3
[junit4:junit4] 2> 1855281 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1437698514903629824)]} 0 0
[junit4:junit4] 2> 1855287 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1437698514907824128)]} 0 0
[junit4:junit4] 2> 1855288 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1437698514907824128)]} 0 3
[junit4:junit4] 2> 1855291 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1437698514914115584)]} 0 0
[junit4:junit4] 2> 1855296 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1437698514917261312)]} 0 0
[junit4:junit4] 2> 1855297 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1437698514917261312)]} 0 3
[junit4:junit4] 2> 1855299 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1437698514922504192)]} 0 0
[junit4:junit4] 2> 1855306 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[62 (1437698514927747072)]} 0 0
[junit4:junit4] 2> 1855307 T3979 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[62 (1437698514927747072)]} 0 3
[junit4:junit4] 2> 1855307 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62]} 0 5
[junit4:junit4] 2> 1855310 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1437698514934038528)]} 0 0
[junit4:junit4] 2> 1855317 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[63 (1437698514939281408)]} 0 0
[junit4:junit4] 2> 1855318 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[63 (1437698514939281408)]} 0 3
[junit4:junit4] 2> 1855318 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63]} 0 5
[junit4:junit4] 2> 1855321 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1437698514945572864)]} 0 0
[junit4:junit4] 2> 1855326 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[64 (1437698514948718592)]} 0 0
[junit4:junit4] 2> 1855327 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1437698514948718592)]} 0 3
[junit4:junit4] 2> 1855330 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1437698514955010048)]} 0 0
[junit4:junit4] 2> 1855337 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[65 (1437698514960252928)]} 0 0
[junit4:junit4] 2> 1855338 T3961 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[65 (1437698514960252928)]} 0 3
[junit4:junit4] 2> 1855338 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65]} 0 5
[junit4:junit4] 2> 1855342 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1437698514967592960)]} 0 0
[junit4:junit4] 2> 1855348 T3991 C2024 P24221 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[66 (1437698514971787264)]} 0 0
[junit4:junit4] 2> 1855349 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1437698514971787264)]} 0 3
[junit4:junit4] 2> 1855351 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1437698514977030144)]} 0 0
[junit4:junit4] 2> 1855356 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[67 (1437698514980175872)]} 0 0
[junit4:junit4] 2> 1855357 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1437698514980175872)]} 0 3
[junit4:junit4] 2> 1855359 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1437698514985418752)]} 0 0
[junit4:junit4] 2> 1855366 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[68 (1437698514990661632)]} 0 0
[junit4:junit4] 2> 1855367 T3979 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26734/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[68 (1437698514990661632)]} 0 3
[junit4:junit4] 2> 1855367 T3963 C2023 P26734 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68]} 0 5
[junit4:junit4] 2> 1855370 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69 (1437698514996953088)]} 0 0
[junit4:junit4] 2> 1855375 T4006 C2020 P40144 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:26312/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[69 (1437698515000098816)]} 0 0
[junit4:junit4] 2> 1855376 T3977 C2021 P26312 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69 (1437698515000098816)]} 0 3
[junit4:junit4] 2> 1855378 T3937 C2022 P60390 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update p
[...truncated too long message...]
r
[junit4:junit4] 2> 2086915 T4016 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 2086923 T4016 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 2086923 T4016 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 2086923 T4016 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4;done=false>>]
[junit4:junit4] 2> 2086924 T4016 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4
[junit4:junit4] 2> 2086924 T4016 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4/index;done=false>>]
[junit4:junit4] 2> 2086924 T4016 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371096118255/jetty4/index
[junit4:junit4] 2> 2086924 T4016 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 2086925 T4016 oasc.LeaderElector$1.process WARN org.apache.zookeeper.KeeperException$SessionExpiredException: KeeperErrorCode = Session expired for /collections/collection1/leader_elect/shard2/election/89856155206680588-5-n_0000000001
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:127)
[junit4:junit4] 2> at org.apache.zookeeper.KeeperException.create(KeeperException.java:51)
[junit4:junit4] 2> at org.apache.zookeeper.ZooKeeper.delete(ZooKeeper.java:873)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:152)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient$2.execute(SolrZkClient.java:149)
[junit4:junit4] 2> at org.apache.solr.common.cloud.ZkCmdExecutor.retryOperation(ZkCmdExecutor.java:65)
[junit4:junit4] 2> at org.apache.solr.common.cloud.SolrZkClient.delete(SolrZkClient.java:149)
[junit4:junit4] 2> at org.apache.solr.cloud.ElectionContext.cancelElection(ElectionContext.java:63)
[junit4:junit4] 2> at org.apache.solr.cloud.ShardLeaderElectionContext.runLeaderProcess(ElectionContext.java:260)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.runIamLeaderProcess(LeaderElector.java:156)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.checkIfIamLeader(LeaderElector.java:100)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector.access$000(LeaderElector.java:55)
[junit4:junit4] 2> at org.apache.solr.cloud.LeaderElector$1.process(LeaderElector.java:129)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.processEvent(ClientCnxn.java:519)
[junit4:junit4] 2> at org.apache.zookeeper.ClientCnxn$EventThread.run(ClientCnxn.java:495)
[junit4:junit4] 2>
[junit4:junit4] 2> 2086925 T4016 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2086926 T4016 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> 2086926 T4016 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2086926 T4016 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> 2086926 T4016 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 2086926 T4016 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=Lucene41, sim=DefaultSimilarity, locale=en_GB, timezone=SystemV/YST9
[junit4:junit4] 2> NOTE: FreeBSD 9.1-RELEASE-p3 amd64/Sun Microsystems Inc. 1.6.0_32 (64-bit)/cpus=16,threads=2,free=313647864,total=475922432
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SolrCmdDistributorTest, SpellPossibilityIteratorTest, TestSolrJ, LeaderElectionIntegrationTest, TestSerializedLuceneMatchVersion, SpellCheckCollatorTest, TestBM25SimilarityFactory, DisMaxRequestHandlerTest, TestZkChroot, TestQueryTypes, OpenCloseCoreStressTest, TestFoldingMultitermQuery, SortByFunctionTest, DistanceFunctionTest, ShardRoutingCustomTest, CollectionsAPIDistributedZkTest, TestAddFieldRealTimeGet, TestCSVLoader, ClusterStateTest, BasicDistributedZk2Test, TestRecovery, TermVectorComponentDistributedTest, FileUtilsTest, TestRTGBase, CurrencyFieldOpenExchangeTest, TestLMJelinekMercerSimilarityFactory, EchoParamsTest, IndexReaderFactoryTest, TestSolr4Spatial, TestComponentsName, UpdateParamsTest, TestDFRSimilarityFactory, SuggesterTSTTest, TestFiltering, NotRequiredUniqueKeyTest, TestShardHandlerFactory, TestSystemIdResolver, HighlighterConfigTest, NoCacheHeaderTest, DefaultValueUpdateProcessorTest, TestAnalyzedSuggestions, TestHashPartitioner, SolrPluginUtilsTest, TestLazyCores, PathHierarchyTokenizerFactoryTest, SuggesterWFSTTest, TestStressReorder, ChaosMonkeySafeLeaderTest, TestSolrQueryParserResource, SolrCoreCheckLockOnStartupTest, TestJmxIntegration, TestPropInject, TestFieldTypeCollectionResource, FieldAnalysisRequestHandlerTest, TestDefaultSimilarityFactory, TestCodecSupport, TimeZoneUtilsTest, PingRequestHandlerTest, TestQuerySenderNoQuery, TestNumberUtils, ZkSolrClientTest, TestSolrQueryParserDefaultOperatorResource, StatsComponentTest, XsltUpdateRequestHandlerTest, HardAutoCommitTest, TestFieldResource, TestIndexSearcher, TestUpdate, DebugComponentTest, JSONWriterTest, TestClassNameShortening, BasicDistributedZkTest, ShardRoutingTest, BasicZkTest, TestRandomFaceting, TestFaceting, TestJoin, QueryElevationComponentTest, BadIndexSchemaTest, BasicFunctionalityTest, OverseerCollectionProcessorTest, SoftAutoCommitTest, TestCoreDiscovery, SuggesterFSTTest, DocValuesTest, TestStressLucene, TestPseudoReturnFields, TestWordDelimiterFilterFactory, TestRemoteStreaming, SolrInfoMBeanTest, StandardRequestHandlerTest, DocumentAnalysisRequestHandlerTest, PrimitiveFieldTypeTest, TermsComponentTest, RequestHandlersTest, TestIndexingPerformance, TestSolrQueryParser, IndexSchemaRuntimeFieldTest, IndexSchemaTest, TestCSVResponseWriter, UniqFieldsUpdateProcessorFactoryTest, TestPartialUpdateDeduplication, CSVRequestHandlerTest, TestBinaryResponseWriter, SOLR749Test, TestSolrIndexConfig, ResponseLogComponentTest, TestMergePolicyConfig, TestSolrDeletionPolicy2, MultiTermTest, SampleTest, TestBinaryField, MinimalSchemaTest, OutputWriterTest, ExternalFileFieldSortTest, TestPostingsSolrHighlighter, LegacyHTMLStripCharFilterTest, ResourceLoaderTest, ScriptEngineTest, PluginInfoTest, TestFastLRUCache, DateMathParserTest, ChaosMonkeyNothingIsSafeTest, TestSolrXMLSerializer, TestSuggestSpellingConverter, SpellingQueryConverterTest, TestUtils, ZkNodePropsTest, CircularListTest, TestCollationKeyRangeQueries, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J1 in 262.54s, 1 test, 1 error <<< FAILURES!
[...truncated 52 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: 60 minutes 58 seconds
Build step 'Invoke Ant' marked build as failure
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure