You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by Policeman Jenkins Server <je...@thetaphi.de> on 2013/06/17 07:39:33 UTC
[JENKINS] Lucene-Solr-4.x-MacOSX (64bit/jdk1.7.0) - Build # 553 -
Still Failing!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-4.x-MacOSX/553/
Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseG1GC
1 tests failed.
FAILED: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:53967 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:53967 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([8A1CE28C26DBA89F:BFA6C945184C8A3]: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:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 10196 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 3436331 T6875 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 3436336 T6875 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./solrtest-ChaosMonkeyShardSplitTest-1371447238602
[junit4:junit4] 2> 3436339 T6875 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 3436340 T6876 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 3436442 T6875 oasc.ZkTestServer.run start zk server on port:53959
[junit4:junit4] 2> 3436445 T6875 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3436452 T6882 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3942b8b0 name:ZooKeeperConnection Watcher:127.0.0.1:53959 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3436452 T6875 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3436453 T6875 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 3436463 T6875 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3436470 T6884 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@196e8d4b name:ZooKeeperConnection Watcher:127.0.0.1:53959/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3436470 T6875 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3436471 T6875 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 3436479 T6875 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 3436487 T6875 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 3436494 T6875 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 3436502 T6875 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 3436503 T6875 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 3436516 T6875 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 3436517 T6875 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 3436525 T6875 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 3436527 T6875 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 3436535 T6875 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 3436536 T6875 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 3436544 T6875 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 3436546 T6875 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 3436554 T6875 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 3436555 T6875 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 3436562 T6875 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 3436563 T6875 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 3436570 T6875 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 3436571 T6875 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 3436579 T6875 oasc.AbstractZkTestCase.putConfig put /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 3436581 T6875 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 3437111 T6875 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 3437123 T6875 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53962
[junit4:junit4] 2> 3437124 T6875 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3437125 T6875 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3437126 T6875 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371447238854
[junit4:junit4] 2> 3437127 T6875 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371447238854/solr.xml
[junit4:junit4] 2> 3437127 T6875 oasc.CoreContainer.<init> New CoreContainer 2118768973
[junit4:junit4] 2> 3437128 T6875 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371447238854/'
[junit4:junit4] 2> 3437129 T6875 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371447238854/'
[junit4:junit4] 2> 3437309 T6875 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 3437310 T6875 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 3437310 T6875 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 3437311 T6875 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 3437311 T6875 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 3437312 T6875 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 3437313 T6875 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 3437313 T6875 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 3437314 T6875 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 3437315 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 3437344 T6875 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 3437345 T6875 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53959/solr
[junit4:junit4] 2> 3437346 T6875 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 3437349 T6875 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3437353 T6895 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3026ec89 name:ZooKeeperConnection Watcher:127.0.0.1:53959 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3437354 T6875 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3437359 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 3437382 T6875 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3437387 T6897 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@52cb2ffc name:ZooKeeperConnection Watcher:127.0.0.1:53959/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3437388 T6875 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3437392 T6875 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 3437402 T6875 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 3437411 T6875 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 3437417 T6875 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53962_
[junit4:junit4] 2> 3437420 T6875 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53962_
[junit4:junit4] 2> 3437429 T6875 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 3437443 T6875 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 3437450 T6875 oasc.Overseer.start Overseer (id=89879166229610499-127.0.0.1:53962_-n_0000000000) starting
[junit4:junit4] 2> 3437459 T6875 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 3437470 T6899 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 3437472 T6875 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 3437479 T6875 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 3437484 T6875 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3437493 T6898 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 3437500 T6900 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 3437500 T6900 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3439005 T6898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3439007 T6898 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53962_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53962"}
[junit4:junit4] 2> 3439007 T6898 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 3439008 T6898 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 3439018 T6897 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> 3439505 T6900 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371447238854/collection1
[junit4:junit4] 2> 3439505 T6900 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 3439507 T6900 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 3439508 T6900 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 3439512 T6900 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371447238854/collection1/'
[junit4:junit4] 2> 3439515 T6900 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371447238854/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 3439516 T6900 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371447238854/collection1/lib/README' to classloader
[junit4:junit4] 2> 3439614 T6900 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 3439714 T6900 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 3439718 T6900 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 3439729 T6900 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 3440689 T6900 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 3440695 T6900 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 3440697 T6900 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 3440708 T6900 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 3440779 T6900 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 3440779 T6900 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1371447238854/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/control/data/
[junit4:junit4] 2> 3440780 T6900 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@248e68a2
[junit4:junit4] 2> 3440780 T6900 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 3440781 T6900 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/control/data
[junit4:junit4] 2> 3440781 T6900 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/control/data/index/
[junit4:junit4] 2> 3440782 T6900 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 3440783 T6900 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/control/data/index
[junit4:junit4] 2> 3440790 T6900 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@254d7a0f lockFactory=org.apache.lucene.store.NativeFSLockFactory@29972d66),segFN=segments_1,generation=1}
[junit4:junit4] 2> 3440791 T6900 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 3440795 T6900 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 3440796 T6900 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 3440797 T6900 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 3440799 T6900 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 3440800 T6900 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 3440800 T6900 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 3440801 T6900 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 3440802 T6900 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 3440802 T6900 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 3440822 T6900 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 3440834 T6900 oass.SolrIndexSearcher.<init> Opening Searcher@40aa2df main
[junit4:junit4] 2> 3440835 T6900 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/control/data/tlog
[junit4:junit4] 2> 3440837 T6900 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 3440837 T6900 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 3440842 T6902 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@40aa2df main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 3440844 T6900 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 3440844 T6900 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53962 collection:control_collection shard:shard1
[junit4:junit4] 2> 3440846 T6900 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 3440869 T6900 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 3440878 T6900 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 3440879 T6900 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 3440879 T6900 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53962/collection1/
[junit4:junit4] 2> 3440879 T6900 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 3440880 T6900 oasc.SyncStrategy.syncToMe http://127.0.0.1:53962/collection1/ has no replicas
[junit4:junit4] 2> 3440880 T6900 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53962/collection1/
[junit4:junit4] 2> 3440881 T6900 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 3442036 T6898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3442057 T6897 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> 3442080 T6900 oasc.ZkController.register We are http://127.0.0.1:53962/collection1/ and leader is http://127.0.0.1:53962/collection1/
[junit4:junit4] 2> 3442081 T6900 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53962
[junit4:junit4] 2> 3442081 T6900 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3442081 T6900 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3442082 T6900 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3442086 T6900 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3442088 T6875 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 3442089 T6875 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3442090 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3442115 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 3442118 T6875 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3442124 T6905 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@79a37f24 name:ZooKeeperConnection Watcher:127.0.0.1:53959/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3442124 T6875 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3442127 T6875 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3442134 T6875 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 3442626 T6875 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 3442634 T6875 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53967
[junit4:junit4] 2> 3442636 T6875 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3442637 T6875 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3442637 T6875 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371447244399
[junit4:junit4] 2> 3442638 T6875 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371447244399/solr.xml
[junit4:junit4] 2> 3442638 T6875 oasc.CoreContainer.<init> New CoreContainer 303166055
[junit4:junit4] 2> 3442639 T6875 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371447244399/'
[junit4:junit4] 2> 3442639 T6875 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371447244399/'
[junit4:junit4] 2> 3442795 T6875 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 3442796 T6875 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 3442797 T6875 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 3442797 T6875 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 3442798 T6875 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 3442799 T6875 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 3442799 T6875 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 3442800 T6875 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 3442801 T6875 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 3442802 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 3442826 T6875 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 3442828 T6875 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53959/solr
[junit4:junit4] 2> 3442828 T6875 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 3442831 T6875 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3442836 T6916 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@446fcf5c name:ZooKeeperConnection Watcher:127.0.0.1:53959 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3442837 T6875 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3442842 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 3442865 T6875 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3442869 T6918 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@da8a0cf name:ZooKeeperConnection Watcher:127.0.0.1:53959/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3442870 T6875 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3442881 T6875 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3443577 T6898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3443579 T6898 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53962__collection1",
[junit4:junit4] 2> "numShards":"1",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"control_collection",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53962_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53962"}
[junit4:junit4] 2> 3443603 T6905 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> 3443604 T6918 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> 3443605 T6897 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> 3443893 T6875 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53967_
[junit4:junit4] 2> 3443899 T6875 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53967_
[junit4:junit4] 2> 3443908 T6918 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 3443909 T6897 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 3443911 T6905 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 3443911 T6905 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> 3443916 T6897 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 3443916 T6918 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 3443929 T6919 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 3443930 T6919 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3445121 T6898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3445123 T6898 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53967_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53967"}
[junit4:junit4] 2> 3445123 T6898 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 3445123 T6898 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 3445133 T6918 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> 3445134 T6905 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> 3445133 T6897 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> 3445936 T6919 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371447244399/collection1
[junit4:junit4] 2> 3445936 T6919 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 3445938 T6919 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 3445938 T6919 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 3445942 T6919 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371447244399/collection1/'
[junit4:junit4] 2> 3445944 T6919 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371447244399/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 3445944 T6919 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371447244399/collection1/lib/README' to classloader
[junit4:junit4] 2> 3446025 T6919 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 3446111 T6919 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 3446115 T6919 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 3446124 T6919 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 3447032 T6919 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 3447038 T6919 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 3447041 T6919 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 3447053 T6919 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 3447132 T6919 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 3447133 T6919 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1371447244399/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty1/
[junit4:junit4] 2> 3447133 T6919 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@248e68a2
[junit4:junit4] 2> 3447134 T6919 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 3447135 T6919 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty1
[junit4:junit4] 2> 3447135 T6919 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty1/index/
[junit4:junit4] 2> 3447136 T6919 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 3447138 T6919 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty1/index
[junit4:junit4] 2> 3447143 T6919 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2d533930 lockFactory=org.apache.lucene.store.NativeFSLockFactory@59872ec4),segFN=segments_1,generation=1}
[junit4:junit4] 2> 3447143 T6919 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 3447148 T6919 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 3447149 T6919 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 3447150 T6919 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 3447151 T6919 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 3447152 T6919 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 3447153 T6919 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 3447153 T6919 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 3447154 T6919 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 3447155 T6919 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 3447184 T6919 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 3447202 T6919 oass.SolrIndexSearcher.<init> Opening Searcher@5645099d main
[junit4:junit4] 2> 3447204 T6919 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty1/tlog
[junit4:junit4] 2> 3447206 T6919 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 3447206 T6919 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 3447215 T6920 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5645099d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 3447220 T6919 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 3447220 T6919 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53967 collection:collection1 shard:shard1
[junit4:junit4] 2> 3447224 T6919 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 3447267 T6919 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 3447287 T6919 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 3447288 T6919 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 3447289 T6919 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53967/collection1/
[junit4:junit4] 2> 3447289 T6919 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 3447290 T6919 oasc.SyncStrategy.syncToMe http://127.0.0.1:53967/collection1/ has no replicas
[junit4:junit4] 2> 3447290 T6919 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53967/collection1/
[junit4:junit4] 2> 3447291 T6919 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 3448156 T6898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3448196 T6905 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> 3448196 T6918 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> 3448197 T6897 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> 3448206 T6919 oasc.ZkController.register We are http://127.0.0.1:53967/collection1/ and leader is http://127.0.0.1:53967/collection1/
[junit4:junit4] 2> 3448206 T6919 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53967
[junit4:junit4] 2> 3448207 T6919 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3448207 T6919 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3448208 T6919 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3448215 T6919 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3448219 T6875 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 3448220 T6875 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3448221 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3448986 T6875 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 3448999 T6875 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53970
[junit4:junit4] 2> 3449003 T6875 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3449004 T6875 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3449005 T6875 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371447250521
[junit4:junit4] 2> 3449006 T6875 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371447250521/solr.xml
[junit4:junit4] 2> 3449007 T6875 oasc.CoreContainer.<init> New CoreContainer 537827487
[junit4:junit4] 2> 3449009 T6875 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371447250521/'
[junit4:junit4] 2> 3449011 T6875 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371447250521/'
[junit4:junit4] 2> 3449511 T6875 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 3449517 T6875 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 3449520 T6875 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 3449522 T6875 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 3449524 T6875 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 3449525 T6875 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 3449526 T6875 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 3449529 T6875 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 3449533 T6875 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 3449534 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 3449583 T6875 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 3449588 T6875 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53959/solr
[junit4:junit4] 2> 3449591 T6875 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 3449595 T6875 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3449605 T6932 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2379b4d7 name:ZooKeeperConnection Watcher:127.0.0.1:53959 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3449611 T6875 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3449622 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 3449676 T6875 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3449685 T6934 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@12b7e218 name:ZooKeeperConnection Watcher:127.0.0.1:53959/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3449688 T6875 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3449717 T6875 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3449748 T6898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3449753 T6898 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53967__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53967_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53967"}
[junit4:junit4] 2> 3449771 T6934 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> 3449772 T6918 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> 3449773 T6905 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> 3449773 T6897 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> 3450739 T6875 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53970_
[junit4:junit4] 2> 3450742 T6875 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53970_
[junit4:junit4] 2> 3450753 T6897 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> 3450753 T6918 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> 3450756 T6905 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 3450757 T6905 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> 3450757 T6934 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 3450758 T6934 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> 3450765 T6897 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 3450766 T6918 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 3450784 T6935 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 3450786 T6935 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3451301 T6898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3451303 T6898 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53970_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53970"}
[junit4:junit4] 2> 3451304 T6898 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 3451304 T6898 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 3451319 T6918 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> 3451319 T6934 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> 3451319 T6905 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> 3451320 T6897 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> 3451791 T6935 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371447250521/collection1
[junit4:junit4] 2> 3451792 T6935 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 3451795 T6935 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 3451798 T6935 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 3451807 T6935 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371447250521/collection1/'
[junit4:junit4] 2> 3451809 T6935 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371447250521/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 3451810 T6935 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371447250521/collection1/lib/README' to classloader
[junit4:junit4] 2> 3451926 T6935 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 3452033 T6935 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 3452045 T6935 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 3452057 T6935 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 3453090 T6935 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 3453095 T6935 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 3453099 T6935 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 3453108 T6935 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 3453228 T6935 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 3453229 T6935 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1371447250521/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty2/
[junit4:junit4] 2> 3453230 T6935 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@248e68a2
[junit4:junit4] 2> 3453231 T6935 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 3453232 T6935 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty2
[junit4:junit4] 2> 3453233 T6935 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty2/index/
[junit4:junit4] 2> 3453233 T6935 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 3453235 T6935 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty2/index
[junit4:junit4] 2> 3453240 T6935 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@46a31163 lockFactory=org.apache.lucene.store.NativeFSLockFactory@330cea7b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 3453241 T6935 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 3453246 T6935 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 3453247 T6935 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 3453248 T6935 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 3453250 T6935 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 3453251 T6935 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 3453251 T6935 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 3453252 T6935 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 3453253 T6935 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 3453253 T6935 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 3453274 T6935 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 3453284 T6935 oass.SolrIndexSearcher.<init> Opening Searcher@6f19a5f0 main
[junit4:junit4] 2> 3453284 T6935 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty2/tlog
[junit4:junit4] 2> 3453286 T6935 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 3453286 T6935 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 3453293 T6936 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@6f19a5f0 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 3453297 T6935 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 3453298 T6935 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53970 collection:collection1 shard:shard2
[junit4:junit4] 2> 3453300 T6935 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 3453317 T6935 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 3453325 T6935 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 3453326 T6935 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 3453326 T6935 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:53970/collection1/
[junit4:junit4] 2> 3453327 T6935 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 3453328 T6935 oasc.SyncStrategy.syncToMe http://127.0.0.1:53970/collection1/ has no replicas
[junit4:junit4] 2> 3453328 T6935 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:53970/collection1/
[junit4:junit4] 2> 3453329 T6935 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 3454345 T6898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3454369 T6897 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> 3454370 T6905 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> 3454370 T6934 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> 3454370 T6918 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> 3454383 T6935 oasc.ZkController.register We are http://127.0.0.1:53970/collection1/ and leader is http://127.0.0.1:53970/collection1/
[junit4:junit4] 2> 3454384 T6935 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53970
[junit4:junit4] 2> 3454384 T6935 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 3454385 T6935 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3454385 T6935 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3454390 T6935 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3454393 T6875 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 3454394 T6875 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3454395 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3455265 T6875 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 3455272 T6875 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53973
[junit4:junit4] 2> 3455276 T6875 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3455277 T6875 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3455278 T6875 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371447256689
[junit4:junit4] 2> 3455278 T6875 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371447256689/solr.xml
[junit4:junit4] 2> 3455279 T6875 oasc.CoreContainer.<init> New CoreContainer 105663498
[junit4:junit4] 2> 3455280 T6875 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371447256689/'
[junit4:junit4] 2> 3455281 T6875 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371447256689/'
[junit4:junit4] 2> 3455550 T6875 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 3455551 T6875 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 3455551 T6875 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 3455552 T6875 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 3455553 T6875 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 3455553 T6875 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 3455555 T6875 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 3455556 T6875 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 3455556 T6875 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 3455557 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 3455596 T6875 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 3455597 T6875 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53959/solr
[junit4:junit4] 2> 3455598 T6875 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 3455607 T6875 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3455621 T6948 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@59930e08 name:ZooKeeperConnection Watcher:127.0.0.1:53959 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3455630 T6875 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3455642 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 3455671 T6875 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3455676 T6950 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@3f844c92 name:ZooKeeperConnection Watcher:127.0.0.1:53959/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3455677 T6875 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3455696 T6875 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3455891 T6898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3455894 T6898 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53970__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53970_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53970"}
[junit4:junit4] 2> 3455907 T6934 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> 3455907 T6950 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> 3455907 T6918 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> 3455908 T6897 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> 3455908 T6905 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> 3456714 T6875 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53973_
[junit4:junit4] 2> 3456717 T6875 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53973_
[junit4:junit4] 2> 3456723 T6897 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> 3456723 T6918 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> 3456727 T6950 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 3456728 T6950 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> 3456727 T6934 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 3456729 T6934 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> 3456727 T6905 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 3456729 T6905 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> 3456733 T6897 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 3456736 T6918 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 3456748 T6951 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 3456749 T6951 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3457440 T6898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3457442 T6898 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53973_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53973"}
[junit4:junit4] 2> 3457443 T6898 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 3457443 T6898 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 3457453 T6905 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> 3457454 T6934 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> 3457454 T6950 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> 3457454 T6918 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> 3457454 T6897 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> 3457754 T6951 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371447256689/collection1
[junit4:junit4] 2> 3457755 T6951 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 3457757 T6951 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 3457757 T6951 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 3457761 T6951 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371447256689/collection1/'
[junit4:junit4] 2> 3457762 T6951 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371447256689/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 3457763 T6951 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371447256689/collection1/lib/README' to classloader
[junit4:junit4] 2> 3457847 T6951 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 3457942 T6951 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 3457946 T6951 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 3457955 T6951 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 3458854 T6951 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 3458859 T6951 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 3458862 T6951 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 3458871 T6951 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 3458940 T6951 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 3458941 T6951 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1371447256689/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty3/
[junit4:junit4] 2> 3458941 T6951 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@248e68a2
[junit4:junit4] 2> 3458942 T6951 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 3458944 T6951 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty3
[junit4:junit4] 2> 3458944 T6951 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty3/index/
[junit4:junit4] 2> 3458945 T6951 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 3458946 T6951 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty3/index
[junit4:junit4] 2> 3458952 T6951 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3f657bb3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28fe3434),segFN=segments_1,generation=1}
[junit4:junit4] 2> 3458952 T6951 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 3458957 T6951 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 3458958 T6951 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 3458959 T6951 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 3458960 T6951 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 3458961 T6951 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 3458961 T6951 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 3458962 T6951 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 3458963 T6951 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 3458964 T6951 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 3458984 T6951 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 3458994 T6951 oass.SolrIndexSearcher.<init> Opening Searcher@7719725d main
[junit4:junit4] 2> 3458995 T6951 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty3/tlog
[junit4:junit4] 2> 3458997 T6951 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 3458998 T6951 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 3459003 T6952 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@7719725d main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 3459006 T6951 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 3459007 T6951 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53973 collection:collection1 shard:shard1
[junit4:junit4] 2> 3459014 T6951 oasc.ZkController.register We are http://127.0.0.1:53973/collection1/ and leader is http://127.0.0.1:53967/collection1/
[junit4:junit4] 2> 3459015 T6951 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53973
[junit4:junit4] 2> 3459015 T6951 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 3459015 T6951 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1521 name=collection1 org.apache.solr.core.SolrCore@5c1493ce url=http://127.0.0.1:53973/collection1 node=127.0.0.1:53973_ C1521_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:53973_, base_url=http://127.0.0.1:53973}
[junit4:junit4] 2> 3459017 T6953 C1521 P53973 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 3459018 T6953 C1521 P53973 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 3459018 T6951 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3459018 T6953 C1521 P53973 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 3459019 T6953 C1521 P53973 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3459021 T6875 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 3459022 T6875 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3459022 T6953 C1521 P53973 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3459023 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3459053 T6910 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:53973__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 3459839 T6875 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 3459856 T6875 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:53977
[junit4:junit4] 2> 3459857 T6875 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 3459858 T6875 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 3459859 T6875 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371447261314
[junit4:junit4] 2> 3459859 T6875 oasc.CoreContainer$Initializer.initialize looking for solr config file: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371447261314/solr.xml
[junit4:junit4] 2> 3459860 T6875 oasc.CoreContainer.<init> New CoreContainer 1534189874
[junit4:junit4] 2> 3459861 T6875 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371447261314/'
[junit4:junit4] 2> 3459862 T6875 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371447261314/'
[junit4:junit4] 2> 3460141 T6875 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 3460142 T6875 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 3460143 T6875 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 3460143 T6875 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 3460144 T6875 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 3460145 T6875 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 3460145 T6875 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 3460147 T6875 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 3460148 T6875 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 3460149 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 3460186 T6875 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 3460187 T6875 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:53959/solr
[junit4:junit4] 2> 3460188 T6875 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 3460191 T6875 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3460206 T6965 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4e44f402 name:ZooKeeperConnection Watcher:127.0.0.1:53959 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3460207 T6875 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3460219 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 3460248 T6875 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 3460258 T6967 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@620247c1 name:ZooKeeperConnection Watcher:127.0.0.1:53959/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 3460262 T6875 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 3460300 T6875 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 3460478 T6898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3460481 T6898 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53973__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53973_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53973"}
[junit4:junit4] 2> 3460502 T6905 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> 3460502 T6918 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> 3460503 T6967 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> 3460504 T6897 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> 3460502 T6934 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> 3460506 T6950 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> 3461058 T6910 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:53973__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 3461059 T6910 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:53973__collection1&state=recovering&nodeName=127.0.0.1:53973_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2006
[junit4:junit4] 2> 3461324 T6875 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:53977_
[junit4:junit4] 2> 3461329 T6875 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:53977_
[junit4:junit4] 2> 3461336 T6918 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> 3461337 T6897 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> 3461342 T6934 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 3461343 T6934 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> 3461342 T6905 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 3461344 T6905 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> 3461344 T6967 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 3461346 T6967 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> 3461344 T6950 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 3461349 T6950 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> 3461349 T6897 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 3461352 T6918 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 3461374 T6968 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 3461375 T6968 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3462031 T6898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3462034 T6898 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":null,
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":null,
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"down",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53977_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53977"}
[junit4:junit4] 2> 3462034 T6898 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 3462035 T6898 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 3462049 T6897 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> 3462049 T6918 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> 3462050 T6905 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> 3462050 T6934 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> 3462050 T6967 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> 3462050 T6950 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> 3462379 T6968 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371447261314/collection1
[junit4:junit4] 2> 3462379 T6968 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 3462381 T6968 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 3462381 T6968 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 3462385 T6968 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371447261314/collection1/'
[junit4:junit4] 2> 3462387 T6968 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371447261314/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 3462388 T6968 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371447261314/collection1/lib/README' to classloader
[junit4:junit4] 2> 3462459 T6968 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_44
[junit4:junit4] 2> 3462555 T6968 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 3462560 T6968 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 3462576 T6968 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> ASYNC NEW_CORE C1522 name=collection1 org.apache.solr.core.SolrCore@5c1493ce url=http://127.0.0.1:53973/collection1 node=127.0.0.1:53973_ C1522_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:53973_, base_url=http://127.0.0.1:53973}
[junit4:junit4] 2> 3463095 T6953 C1522 P53973 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:53967/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 3463096 T6953 C1522 P53973 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53973 START replicas=[http://127.0.0.1:53967/collection1/] nUpdates=100
[junit4:junit4] 2> 3463099 T6953 C1522 P53973 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 3463102 T6953 C1522 P53973 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 3463104 T6953 C1522 P53973 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 3463104 T6953 C1522 P53973 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 3463105 T6953 C1522 P53973 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 3463105 T6953 C1522 P53973 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:53967/collection1/. core=collection1
[junit4:junit4] 2> 3463105 T6953 C1522 P53973 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1523 name=collection1 org.apache.solr.core.SolrCore@3f180342 url=http://127.0.0.1:53967/collection1 node=127.0.0.1:53967_ C1523_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53967_, base_url=http://127.0.0.1:53967, leader=true}
[junit4:junit4] 2> 3463128 T6909 C1523 P53967 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 3463138 T6911 C1523 P53967 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 3463142 T6911 C1523 P53967 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2d533930 lockFactory=org.apache.lucene.store.NativeFSLockFactory@59872ec4),segFN=segments_1,generation=1}
[junit4:junit4] 2> 3463145 T6911 C1523 P53967 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 3463146 T6911 C1523 P53967 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2d533930 lockFactory=org.apache.lucene.store.NativeFSLockFactory@59872ec4),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2d533930 lockFactory=org.apache.lucene.store.NativeFSLockFactory@59872ec4),segFN=segments_2,generation=2}
[junit4:junit4] 2> 3463147 T6911 C1523 P53967 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 3463147 T6911 C1523 P53967 oass.SolrIndexSearcher.<init> Opening Searcher@7953bbe5 realtime
[junit4:junit4] 2> 3463148 T6911 C1523 P53967 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 3463149 T6911 C1523 P53967 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 11
[junit4:junit4] 2> 3463151 T6953 C1522 P53973 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 3463152 T6953 C1522 P53973 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 3463159 T6913 C1523 P53967 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 3463160 T6913 C1523 P53967 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=3
[junit4:junit4] 2> 3463161 T6953 C1522 P53973 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 3463161 T6953 C1522 P53973 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 3463162 T6953 C1522 P53973 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 3463166 T6914 C1523 P53967 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 3463169 T6953 C1522 P53973 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 3463173 T6953 C1522 P53973 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty3/index.20130616183425434
[junit4:junit4] 2> 3463173 T6953 C1522 P53973 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@1a76941b lockFactory=org.apache.lucene.store.NativeFSLockFactory@2d51973b) fullCopy=false
[junit4:junit4] 2> 3463176 T6910 C1523 P53967 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> 3463178 T6953 C1522 P53973 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 3463180 T6953 C1522 P53973 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 3463180 T6953 C1522 P53973 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 3463183 T6953 C1522 P53973 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3f657bb3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28fe3434),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3f657bb3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28fe3434),segFN=segments_2,generation=2}
[junit4:junit4] 2> 3463184 T6953 C1522 P53973 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 3463185 T6953 C1522 P53973 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 3463185 T6953 C1522 P53973 oass.SolrIndexSearcher.<init> Opening Searcher@9585f5a main
[junit4:junit4] 2> 3463188 T6952 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9585f5a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 3463189 T6953 C1522 P53973 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty3/index.20130616183425434 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty3/index.20130616183425434;done=true>>]
[junit4:junit4] 2> 3463189 T6953 C1522 P53973 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty3/index.20130616183425434
[junit4:junit4] 2> 3463190 T6953 C1522 P53973 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty3/index.20130616183425434
[junit4:junit4] 2> 3463190 T6953 C1522 P53973 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 3463190 T6953 C1522 P53973 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 3463191 T6953 C1522 P53973 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3463191 T6953 C1522 P53973 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3463194 T6953 C1522 P53973 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 3463570 T6898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3463571 T6898 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53973__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard1",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53973_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53973"}
[junit4:junit4] 2> 3463582 T6934 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> 3463588 T6918 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> 3463591 T6950 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> 3463592 T6905 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> 3463592 T6897 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> 3463597 T6967 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> 3463685 T6968 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 3463690 T6968 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 3463694 T6968 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 3463709 T6968 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 3463788 T6968 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 3463789 T6968 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1371447261314/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty4/
[junit4:junit4] 2> 3463789 T6968 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@248e68a2
[junit4:junit4] 2> 3463790 T6968 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 3463791 T6968 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty4
[junit4:junit4] 2> 3463791 T6968 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty4/index/
[junit4:junit4] 2> 3463792 T6968 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 3463794 T6968 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty4/index
[junit4:junit4] 2> 3463800 T6968 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@70699bd6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@39236410),segFN=segments_1,generation=1}
[junit4:junit4] 2> 3463800 T6968 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 3463805 T6968 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 3463806 T6968 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 3463807 T6968 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 3463809 T6968 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 3463810 T6968 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 3463810 T6968 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 3463812 T6968 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 3463813 T6968 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 3463813 T6968 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 3463833 T6968 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 3463844 T6968 oass.SolrIndexSearcher.<init> Opening Searcher@47f24fc8 main
[junit4:junit4] 2> 3463845 T6968 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty4/tlog
[junit4:junit4] 2> 3463846 T6968 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 3463847 T6968 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 3463853 T6971 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@47f24fc8 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 3463856 T6968 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 3463857 T6968 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:53977 collection:collection1 shard:shard2
[junit4:junit4] 2> 3463866 T6968 oasc.ZkController.register We are http://127.0.0.1:53977/collection1/ and leader is http://127.0.0.1:53970/collection1/
[junit4:junit4] 2> 3463867 T6968 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:53977
[junit4:junit4] 2> 3463867 T6968 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 3463868 T6968 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C1524 name=collection1 org.apache.solr.core.SolrCore@2842d7b2 url=http://127.0.0.1:53977/collection1 node=127.0.0.1:53977_ C1524_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:53977_, base_url=http://127.0.0.1:53977}
[junit4:junit4] 2> 3463869 T6972 C1524 P53977 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 3463870 T6972 C1524 P53977 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 3463871 T6968 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3463871 T6972 C1524 P53977 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 3463872 T6972 C1524 P53977 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3463874 T6875 oass.SolrDispatchFilter.init user.dir=/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build/solr-core/test/J0
[junit4:junit4] 2> 3463875 T6875 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 3463874 T6972 C1524 P53977 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3463877 T6875 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 3463909 T6875 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3463911 T6926 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:53977__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 3463912 T6875 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 3463913 T6875 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 3463916 T6875 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3464922 T6875 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3465094 T6898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3465096 T6898 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53977__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"recovering",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53977_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53977"}
[junit4:junit4] 2> 3465108 T6905 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> 3465108 T6918 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> 3465108 T6934 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> 3465109 T6950 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> 3465108 T6967 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> 3465108 T6897 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> 3465917 T6926 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:53977__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 3465918 T6926 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:53977__collection1&state=recovering&nodeName=127.0.0.1:53977_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2007
[junit4:junit4] 2> 3465930 T6875 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3466935 T6875 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C1524_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:53977_, base_url=http://127.0.0.1:53977}
[junit4:junit4] 2> 3467920 T6972 C1524 P53977 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:53970/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 3467922 T6972 C1524 P53977 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:53977 START replicas=[http://127.0.0.1:53970/collection1/] nUpdates=100
[junit4:junit4] 2> 3467924 T6972 C1524 P53977 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 3467928 T6972 C1524 P53977 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 3467929 T6972 C1524 P53977 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 3467930 T6972 C1524 P53977 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 3467931 T6972 C1524 P53977 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 3467934 T6972 C1524 P53977 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:53970/collection1/. core=collection1
[junit4:junit4] 2> 3467935 T6972 C1524 P53977 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C1525 name=collection1 org.apache.solr.core.SolrCore@7139d87c url=http://127.0.0.1:53970/collection1 node=127.0.0.1:53970_ C1525_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53970_, base_url=http://127.0.0.1:53970, leader=true}
[junit4:junit4] 2> 3467954 T6927 C1525 P53970 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=1
[junit4:junit4] 2> 3467956 T6875 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3467965 T6928 C1525 P53970 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 3467969 T6928 C1525 P53970 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@46a31163 lockFactory=org.apache.lucene.store.NativeFSLockFactory@330cea7b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 3467969 T6928 C1525 P53970 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 3467971 T6928 C1525 P53970 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@46a31163 lockFactory=org.apache.lucene.store.NativeFSLockFactory@330cea7b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@46a31163 lockFactory=org.apache.lucene.store.NativeFSLockFactory@330cea7b),segFN=segments_2,generation=2}
[junit4:junit4] 2> 3467972 T6928 C1525 P53970 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 3467972 T6928 C1525 P53970 oass.SolrIndexSearcher.<init> Opening Searcher@32ae236d realtime
[junit4:junit4] 2> 3467973 T6928 C1525 P53970 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 3467974 T6928 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 9
[junit4:junit4] 2> 3467975 T6972 C1524 P53977 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 3467975 T6972 C1524 P53977 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 3467980 T6930 C1525 P53970 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 3467980 T6930 C1525 P53970 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 3467981 T6972 C1524 P53977 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 3467982 T6972 C1524 P53977 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 3467982 T6972 C1524 P53977 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 3467985 T6926 C1525 P53970 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=1
[junit4:junit4] 2> 3467986 T6972 C1524 P53977 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 3467988 T6972 C1524 P53977 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty4/index.20130616183430250
[junit4:junit4] 2> 3467988 T6972 C1524 P53977 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@58eeaa73 lockFactory=org.apache.lucene.store.NativeFSLockFactory@783b5ca0) fullCopy=false
[junit4:junit4] 2> 3467996 T6925 C1525 P53970 oasc.SolrCore.execute [collection1] webapp= path=/replication params={file=segments_2&command=filecontent&checksum=true&wt=filestream&qt=/replication&generation=2} status=0 QTime=1
[junit4:junit4] 2> 3467998 T6972 C1524 P53977 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 3467999 T6972 C1524 P53977 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 3467999 T6972 C1524 P53977 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 3468002 T6972 C1524 P53977 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@70699bd6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@39236410),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@70699bd6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@39236410),segFN=segments_2,generation=2}
[junit4:junit4] 2> 3468004 T6972 C1524 P53977 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 3468004 T6972 C1524 P53977 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 3468005 T6972 C1524 P53977 oass.SolrIndexSearcher.<init> Opening Searcher@44cc0c5 main
[junit4:junit4] 2> 3468006 T6971 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@44cc0c5 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 3468007 T6972 C1524 P53977 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty4/index.20130616183430250 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty4/index.20130616183430250;done=true>>]
[junit4:junit4] 2> 3468008 T6972 C1524 P53977 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty4/index.20130616183430250
[junit4:junit4] 2> 3468008 T6972 C1524 P53977 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1371447238601/jetty4/index.20130616183430250
[junit4:junit4] 2> 3468008 T6972 C1524 P53977 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 3468009 T6972 C1524 P53977 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 3468009 T6972 C1524 P53977 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 3468009 T6972 C1524 P53977 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 3468012 T6972 C1524 P53977 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 3468142 T6898 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3468146 T6898 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:53977__collection1",
[junit4:junit4] 2> "numShards":"2",
[junit4:junit4] 2> "shard":"shard2",
[junit4:junit4] 2> "roles":null,
[junit4:junit4] 2> "state":"active",
[junit4:junit4] 2> "shard_state":"active",
[junit4:junit4] 2> "core":"collection1",
[junit4:junit4] 2> "collection":"collection1",
[junit4:junit4] 2> "shard_range":null,
[junit4:junit4] 2> "node_name":"127.0.0.1:53977_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:53977"}
[junit4:junit4] 2> 3468173 T6918 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> 3468174 T6967 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> 3468177 T6897 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> 3468174 T6934 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> 3468176 T6905 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> 3468175 T6950 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> 3468968 T6875 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3468973 T6875 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C1526 name=collection1 org.apache.solr.core.SolrCore@479cdbf6 url=http://127.0.0.1:53962/collection1 node=127.0.0.1:53962_ C1526_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:53962_, base_url=http://127.0.0.1:53962, leader=true}
[junit4:junit4] 2> 3469008 T6891 C1526 P53962 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 3469012 T6891 C1526 P53962 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@254d7a0f lockFactory=org.apache.lucene.store.NativeFSLockFactory@29972d66),segFN=segments_1,generation=1}
[junit4:junit4] 2> 3469013 T6891 C1526 P53962 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 3469014 T6891 C1526 P53962 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@254d7a0f lockFactory=org.apache.lucene.store.NativeFSLockFactory@29972d66),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@254d7a0f lockFactory=org.apache.lucene.store.NativeFSLockFactory@29972d66),segFN=segments_2,generation=2}
[junit4:junit4] 2> 3469015 T6891 C1526 P53962 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 3469015 T6891 C1526 P53962 oass.SolrIndexSearcher.<init> Opening Searcher@5caaf5c2 main
[junit4:junit4] 2> 3469016 T6891 C1526 P53962 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 3469017 T6902 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@5caaf5c2 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 3469018 T6891 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 10
[junit4:junit4] 2> 3469040 T6912 C1523 P53967 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 3469041 T6912 C1523 P53967 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2d533930 lockFactory=org.apache.lucene.store.NativeFSLockFactory@59872ec4),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@2d533930 lockFactory=org.apache.lucene.store.NativeFSLockFactory@59872ec4),segFN=segments_3,generation=3}
[junit4:junit4] 2> 3469042 T6912 C1523 P53967 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 3469043 T6912 C1523 P53967 oass.SolrIndexSearcher.<init> Opening Searcher@35b656b2 main
[junit4:junit4] 2> 3469044 T6912 C1523 P53967 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 3469045 T6920 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@35b656b2 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 3469046 T6912 C1523 P53967 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:53973/collection1/, StdNode: http://127.0.0.1:53970/collection1/, StdNode: http://127.0.0.1:53977/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 3469056 T6929 C1525 P53970 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C1522_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53973_, base_url=http://127.0.0.1:53973}
[junit4:junit4] 2> 3469066 T6944 C1522 P53973 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 3469067 T6944 C1522 P53973 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3f657bb3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28fe3434),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3f657bb3 lockFactory=org.apache.lucene.store.NativeFSLockFactory@28fe3434),segFN=segments_3,generation=3}
[junit4:junit4] 2> 3469067 T6929 C1525 P53970 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@46a31163 lockFactory=org.apache.lucene.store.NativeFSLockFactory@330cea7b),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@46a31163 lockFactory=org.apache.lucene.store.NativeFSLockFactory@330cea7b),segFN=segments_3,generation=3}
[junit4:junit4] 2> 3469069 T6944 C1522 P53973 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> C1524_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:53977_, base_url=http://127.0.0.1:53977}
[junit4:junit4] 2> 3469067 T6962 C1524 P53977 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 3469071 T6944 C1522 P53973 oass.SolrIndexSearcher.<init> Opening Searcher@714d36a7 main
[junit4:junit4] 2> 3469070 T6929 C1525 P53970 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 3469073 T6929 C1525 P53970 oass.SolrIndexSearcher.<init> Opening Searcher@63450a1d main
[junit4:junit4] 2> 3469073 T6944 C1522 P53973 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 3469072 T6962 C1524 P53977 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@70699bd6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@39236410),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@70699bd6 lockFactory=org.apache.lucene.store.NativeFSLockFactory@39236410),segFN=segments_3,generation=3}
[junit4:junit4] 2> 3469075 T6962 C1524 P53977 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 3469075 T6936 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@63450a1d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 3469074 T6929 C1525 P53970 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 3469074 T6952 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@714d36a7 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 3469078 T6929 C1525 P53970 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 22
[junit4:junit4] 2> 3469076 T6962 C1524 P53977 oass.SolrIndexSearcher.<init> Opening Searcher@1bba19d9 main
[junit4:junit4] 2> 3469080 T6962 C1524 P53977 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 3469079 T6944 C1522 P53973 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 13
[junit4:junit4] 2> 3469081 T6971 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1bba19d9 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 3469082 T6962 C1524 P53977 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 15
[junit4:junit4] 2> 3469084 T6912 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 44
[junit4:junit4] 2> 3469086 T6875 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 3469091 T6913 C1523 P53967 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> 3469096 T6945 C1522 P53973 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> 3469100 T6930 C1525 P53970 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> 3469104 T6963 C1524 P53977 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> 3471112 T6891 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438066696126464000)} 0 2
[junit4:junit4] 2> 3471125 T6962 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438066696131706880&update.from=http://127.0.0.1:53970/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438066696131706880)} 0 3
[junit4:junit4] 2> 3471131 T6945 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1438066696141144064&update.from=http://127.0.0.1:53967/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1438066696141144064)} 0 2
[junit4:junit4] 2> 3471132 T6914 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1438066696141144064)} 0 7
[junit4:junit4] 2> 3471133 T6929 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1438066696131706880)} 0 17
[junit4:junit4] 2> 3471138 T6892 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1438066696153726976)]} 0 1
[junit4:junit4] 2> 3471150 T6946 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1438066696162115584)]} 0 1
[junit4:junit4] 2> 3471152 T6910 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1438066696162115584)]} 0 7
[junit4:junit4] 2> 3471156 T6893 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1438066696172601344)]} 0 1
[junit4:junit4] 2> 3471166 T6941 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1438066696179941376)]} 0 1
[junit4:junit4] 2> 3471167 T6909 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[1 (1438066696179941376)]} 0 5
[junit4:junit4] 2> 3471169 T6930 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1]} 0 10
[junit4:junit4] 2> 3471174 T6888 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1438066696191475712)]} 0 2
[junit4:junit4] 2> 3471181 T6958 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1438066696196718592)]} 0 0
[junit4:junit4] 2> 3471183 T6926 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1438066696196718592)]} 0 6
[junit4:junit4] 2> 3471187 T6889 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1438066696205107200)]} 0 1
[junit4:junit4] 2> 3471195 T6959 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1438066696210350080)]} 0 0
[junit4:junit4] 2> 3471200 T6925 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1438066696210350080)]} 0 10
[junit4:junit4] 2> 3471203 T6890 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1438066696222932992)]} 0 1
[junit4:junit4] 2> 3471218 T6942 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1438066696231321600)]} 0 1
[junit4:junit4] 2> 3471219 T6911 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1438066696231321600)]} 0 8
[junit4:junit4] 2> 3471223 T6891 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1438066696242855936)]} 0 1
[junit4:junit4] 2> 3471232 T6960 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1438066696249147392)]} 0 1
[junit4:junit4] 2> 3471233 T6927 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[5 (1438066696249147392)]} 0 5
[junit4:junit4] 2> 3471234 T6912 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5]} 0 8
[junit4:junit4] 2> 3471238 T6892 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1438066696259633152)]} 0 0
[junit4:junit4] 2> 3471251 T6961 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1438066696270118912)]} 0 1
[junit4:junit4] 2> 3471252 T6928 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[6 (1438066696270118912)]} 0 4
[junit4:junit4] 2> 3471253 T6913 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6]} 0 12
[junit4:junit4] 2> 3471260 T6893 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1438066696281653248)]} 0 1
[junit4:junit4] 2> 3471273 T6963 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1438066696292139008)]} 0 1
[junit4:junit4] 2> 3471274 T6929 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[7 (1438066696292139008)]} 0 5
[junit4:junit4] 2> 3471275 T6914 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7]} 0 8
[junit4:junit4] 2> 3471280 T6888 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1438066696302624768)]} 0 1
[junit4:junit4] 2> 3471290 T6943 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1438066696308916224)]} 0 1
[junit4:junit4] 2> 3471291 T6910 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1438066696308916224)]} 0 6
[junit4:junit4] 2> 3471295 T6889 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1438066696319401984)]} 0 0
[junit4:junit4] 2> 3471302 T6962 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1438066696323596288)]} 0 1
[junit4:junit4] 2> 3471303 T6930 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1438066696323596288)]} 0 4
[junit4:junit4] 2> 3471306 T6890 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1438066696330936320)]} 0 0
[junit4:junit4] 2> 3471319 T6944 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1438066696341422080)]} 0 1
[junit4:junit4] 2> 3471320 T6909 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1438066696341422080)]} 0 5
[junit4:junit4] 2> 3471324 T6891 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1438066696348762112)]} 0 1
[junit4:junit4] 2> 3471339 T6945 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1438066696362393600)]} 0 1
[junit4:junit4] 2> 3471341 T6911 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[11 (1438066696362393600)]} 0 6
[junit4:junit4] 2> 3471342 T6926 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11]} 0 14
[junit4:junit4] 2> 3471352 T6892 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1438066696379170816)]} 0 1
[junit4:junit4] 2> 3471362 T6946 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1438066696385462272)]} 0 1
[junit4:junit4] 2> 3471364 T6912 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[12 (1438066696385462272)]} 0 6
[junit4:junit4] 2> 3471365 T6925 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12]} 0 9
[junit4:junit4] 2> 3471372 T6893 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1438066696400142336)]} 0 0
[junit4:junit4] 2> 3471383 T6941 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1438066696407482368)]} 0 1
[junit4:junit4] 2> 3471384 T6913 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[13 (1438066696407482368)]} 0 5
[junit4:junit4] 2> 3471386 T6927 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13]} 0 10
[junit4:junit4] 2> 3471390 T6888 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1438066696419016704)]} 0 1
[junit4:junit4] 2> 3471398 T6942 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1438066696423211008)]} 0 1
[junit4:junit4] 2> 3471399 T6914 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1438066696423211008)]} 0 5
[junit4:junit4] 2> 3471405 T6889 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1438066696434745344)]} 0 1
[junit4:junit4] 2> 3471416 T6943 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1438066696442085376)]} 0 1
[junit4:junit4] 2> 3471417 T6910 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1438066696442085376)]} 0 5
[junit4:junit4] 2> 3471426 T6890 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1438066696456765440)]} 0 1
[junit4:junit4] 2> 3471437 T6944 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1438066696463056896)]} 0 1
[junit4:junit4] 2> 3471438 T6909 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1438066696463056896)]} 0 6
[junit4:junit4] 2> 3471442 T6892 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1438066696473542656)]} 0 0
[junit4:junit4] 2> 3471455 T6958 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1438066696481931264)]} 0 1
[junit4:junit4] 2> 3471456 T6928 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[17 (1438066696481931264)]} 0 6
[junit4:junit4] 2> 3471458 T6911 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17]} 0 11
[junit4:junit4] 2> 3471466 T6893 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1438066696498708480)]} 0 1
[junit4:junit4] 2> 3471476 T6959 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1438066696504999936)]} 0 1
[junit4:junit4] 2> 3471477 T6929 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[18 (1438066696504999936)]} 0 5
[junit4:junit4] 2> 3471479 T6912 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18]} 0 9
[junit4:junit4] 2> 3471483 T6888 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1438066696515485696)]} 0 1
[junit4:junit4] 2> 3471496 T6960 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1438066696523874304)]} 0 0
[junit4:junit4] 2> 3471498 T6930 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[19 (1438066696523874304)]} 0 9
[junit4:junit4] 2> 3471499 T6913 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19]} 0 12
[junit4:junit4] 2> 3471504 T6889 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1438066696537505792)]} 0 1
[junit4:junit4] 2> 3471511 T6945 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1438066696542748672)]} 0 1
[junit4:junit4] 2> 3471513 T6914 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1438066696542748672)]} 0 6
[junit4:junit4] 2> 3471517 T6890 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1438066696551137280)]} 0 1
[junit4:junit4] 2> 3471524 T6961 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1438066696556380160)]} 0 1
[junit4:junit4] 2> 3471526 T6926 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1438066696556380160)]} 0 6
[junit4:junit4] 2> 3471531 T6891 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1438066696565817344)]} 0 1
[junit4:junit4] 2> 3471541 T6941 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1438066696571060224)]} 0 1
[junit4:junit4] 2> 3471543 T6909 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1438066696571060224)]} 0 8
[junit4:junit4] 2> 3471548 T6892 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1438066696583643136)]} 0 2
[junit4:junit4] 2> 3471569 T6962 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1438066696602517504)]} 0 0
[junit4:junit4] 2> 3471571 T6927 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[23 (1438066696602517504)]} 0 6
[junit4:junit4] 2> 3471572 T6911 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23]} 0 16
[junit4:junit4] 2> 3471575 T6893 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1438066696613003264)]} 0 0
[junit4:junit4] 2> 3471584 T6942 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1438066696618246144)]} 0 1
[junit4:junit4] 2> 3471585 T6912 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1438066696618246144)]} 0 5
[junit4:junit4] 2> 3471590 T6888 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1438066696627683328)]} 0 1
[junit4:junit4] 2> 3471606 T6958 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1438066696640266240)]} 0 1
[junit4:junit4] 2> 3471608 T6928 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[25 (1438066696640266240)]} 0 8
[junit4:junit4] 2> 3471609 T6913 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25]} 0 14
[junit4:junit4] 2> 3471613 T6889 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1438066696651800576)]} 0 1
[junit4:junit4] 2> 3471626 T6959 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1438066696661237760)]} 0 1
[junit4:junit4] 2> 3471628 T6929 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[26 (1438066696661237760)]} 0 8
[junit4:junit4] 2> 3471629 T6910 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26]} 0 13
[junit4:junit4] 2> 3471633 T6890 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1438066696672772096)]} 0 1
[junit4:junit4] 2> 3471646 T6943 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1438066696682209280)]} 0 2
[junit4:junit4] 2> 3471647 T6914 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[27 (1438066696682209280)]} 0 6
[junit4:junit4] 2> 3471649 T6930 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27]} 0 12
[junit4:junit4] 2> 3471655 T6891 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1438066696695840768)]} 0 1
[junit4:junit4] 2> 3471664 T6944 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1438066696702132224)]} 0 1
[junit4:junit4] 2> 3471666 T6909 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1438066696702132224)]} 0 6
[junit4:junit4] 2> 3471673 T6892 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1438066696715763712)]} 0 1
[junit4:junit4] 2> 3471684 T6960 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1438066696722055168)]} 0 1
[junit4:junit4] 2> 3471685 T6925 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1438066696722055168)]} 0 6
[junit4:junit4] 2> 3471689 T6893 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1438066696732540928)]} 0 1
[junit4:junit4] 2> 3471705 T6963 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1438066696745123840)]} 0 1
[junit4:junit4] 2> 3471706 T6926 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[30 (1438066696745123840)]} 0 6
[junit4:junit4] 2> 3471707 T6911 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30]} 0 12
[junit4:junit4] 2> 3471712 T6888 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1438066696755609600)]} 0 0
[junit4:junit4] 2> 3471723 T6961 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1438066696762949632)]} 0 1
[junit4:junit4] 2> 3471725 T6927 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[31 (1438066696762949632)]} 0 7
[junit4:junit4] 2> 3471726 T6912 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31]} 0 11
[junit4:junit4] 2> 3471730 T6889 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1438066696775532544)]} 0 1
[junit4:junit4] 2> 3471738 T6946 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1438066696779726848)]} 0 1
[junit4:junit4] 2> 3471739 T6913 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1438066696779726848)]} 0 5
[junit4:junit4] 2> 3471743 T6890 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1438066696788115456)]} 0 1
[junit4:junit4] 2> 3471753 T6962 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1438066696795455488)]} 0 1
[junit4:junit4] 2> 3471754 T6928 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[33 (1438066696795455488)]} 0 5
[junit4:junit4] 2> 3471755 T6910 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33]} 0 9
[junit4:junit4] 2> 3471761 T6891 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1438066696808038400)]} 0 1
[junit4:junit4] 2> 3471768 T6945 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1438066696812232704)]} 0 0
[junit4:junit4] 2> 3471770 T6914 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1438066696812232704)]} 0 5
[junit4:junit4] 2> 3471776 T6892 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1438066696822718464)]} 0 1
[junit4:junit4] 2> 3471786 T6941 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1438066696830058496)]} 0 1
[junit4:junit4] 2> 3471787 T6909 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[35 (1438066696830058496)]} 0 5
[junit4:junit4] 2> 3471789 T6929 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35]} 0 10
[junit4:junit4] 2> 3471793 T6893 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1438066696840544256)]} 0 1
[junit4:junit4] 2> 3471806 T6942 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1438066696848932864)]} 0 1
[junit4:junit4] 2> 3471807 T6911 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[36 (1438066696848932864)]} 0 7
[junit4:junit4] 2> 3471809 T6930 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36]} 0 12
[junit4:junit4] 2> 3471812 T6888 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1438066696861515776)]} 0 0
[junit4:junit4] 2> 3471820 T6958 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1438066696866758656)]} 0 0
[junit4:junit4] 2> 3471822 T6925 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1438066696866758656)]} 0 5
[junit4:junit4] 2> 3471826 T6889 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1438066696875147264)]} 0 1
[junit4:junit4] 2> 3471840 T6943 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1438066696884584448)]} 0 0
[junit4:junit4] 2> 3471842 T6912 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[38 (1438066696884584448)]} 0 8
[junit4:junit4] 2> 3471843 T6926 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38]} 0 12
[junit4:junit4] 2> 3471848 T6891 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1438066696898215936)]} 0 1
[junit4:junit4] 2> 3471856 T6959 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1438066696903458816)]} 0 1
[junit4:junit4] 2> 3471857 T6927 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1438066696903458816)]} 0 5
[junit4:junit4] 2> 3471866 T6892 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1438066696918138880)]} 0 1
[junit4:junit4] 2> 3471874 T6944 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1438066696922333184)]} 0 1
[junit4:junit4] 2> 3471876 T6913 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1438066696922333184)]} 0 6
[junit4:junit4] 2> 3471880 T6893 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1438066696932818944)]} 0 1
[junit4:junit4] 2> 3471890 T6946 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1438066696939110400)]} 0 1
[junit4:junit4] 2> 3471892 T6910 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[41 (1438066696939110400)]} 0 6
[junit4:junit4] 2> 3471893 T6928 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41]} 0 9
[junit4:junit4] 2> 3471900 T6888 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1438066696952741888)]} 0 1
[junit4:junit4] 2> 3471908 T6945 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1438066696957984768)]} 0 1
[junit4:junit4] 2> 3471909 T6914 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1438066696957984768)]} 0 5
[junit4:junit4] 2> 3471914 T6889 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1438066696967421952)]} 0 1
[junit4:junit4] 2> 3471923 T6941 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1438066696971616256)]} 0 1
[junit4:junit4] 2> 3471925 T6911 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1438066696971616256)]} 0 8
[junit4:junit4] 2> 3471929 T6890 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1438066696983150592)]} 0 1
[junit4:junit4] 2> 3471938 T6943 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1438066696989442048)]} 0 1
[junit4:junit4] 2> 3471940 T6912 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1438066696989442048)]} 0 6
[junit4:junit4] 2> 3471944 T6891 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1438066696999927808)]} 0 1
[junit4:junit4] 2> 3471966 T6960 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1438066697014607872)]} 0 1
[junit4:junit4] 2> 3471967 T6929 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[45 (1438066697014607872)]} 0 9
[junit4:junit4] 2> 3471969 T6913 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45]} 0 14
[junit4:junit4] 2> 3471973 T6892 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1438066697029287936)]} 0 1
[junit4:junit4] 2> 3471981 T6944 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1438066697035579392)]} 0 0
[junit4:junit4] 2> 3471983 T6910 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1438066697035579392)]} 0 6
[junit4:junit4] 2> 3471996 T6893 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1438066697053405184)]} 0 1
[junit4:junit4] 2> 3472006 T6946 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1438066697058648064)]} 0 1
[junit4:junit4] 2> 3472007 T6914 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1438066697058648064)]} 0 7
[junit4:junit4] 2> 3472012 T6888 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1438066697071230976)]} 0 1
[junit4:junit4] 2> 3472034 T6945 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1438066697082765312)]} 0 1
[junit4:junit4] 2> 3472036 T6909 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[48 (1438066697082765312)]} 0 14
[junit4:junit4] 2> 3472037 T6925 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48]} 0 19
[junit4:junit4] 2> 3472042 T6889 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1438066697101639680)]} 0 1
[junit4:junit4] 2> 3472052 T6942 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1438066697108979712)]} 0 1
[junit4:junit4] 2> 3472053 T6911 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[49 (1438066697108979712)]} 0 5
[junit4:junit4] 2> 3472055 T6926 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49]} 0 10
[junit4:junit4] 2> 3472059 T6890 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1438066697119465472)]} 0 1
[junit4:junit4] 2> 3472073 T6941 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1438066697130999808)]} 0 1
[junit4:junit4] 2> 3472074 T6912 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[50 (1438066697130999808)]} 0 6
[junit4:junit4] 2> 3472076 T6927 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50]} 0 10
[junit4:junit4] 2> 3472082 T6891 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1438066697143582720)]} 0 2
[junit4:junit4] 2> 3472093 T6943 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1438066697150922752)]} 0 1
[junit4:junit4] 2> 3472095 T6913 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1438066697150922752)]} 0 7
[junit4:junit4] 2> 3472100 T6892 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1438066697162457088)]} 0 1
[junit4:junit4] 2> 3472108 T6944 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1438066697167699968)]} 0 0
[junit4:junit4] 2> 3472109 T6910 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1438066697167699968)]} 0 5
[junit4:junit4] 2> 3472116 T6893 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1438066697180282880)]} 0 1
[junit4:junit4] 2> 3472126 T6961 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1438066697184477184)]} 0 1
[junit4:junit4] 2> 3472127 T6928 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1438066697184477184)]} 0 7
[junit4:junit4] 2> 3472131 T6888 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1438066697194962944)]} 0 1
[junit4:junit4] 2> 3472139 T6946 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1438066697201254400)]} 0 1
[junit4:junit4] 2> 3472140 T6914 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[54 (1438066697201254400)]} 0 4
[junit4:junit4] 2> 3472141 T6930 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54]} 0 7
[junit4:junit4] 2> 3472146 T6889 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1438066697210691584)]} 0 2
[junit4:junit4] 2> 3472159 T6945 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1438066697220128768)]} 0 1
[junit4:junit4] 2> 3472161 T6909 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[55 (1438066697220128768)]} 0 7
[junit4:junit4] 2> 3472163 T6929 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55]} 0 13
[junit4:junit4] 2> 3472169 T6890 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1438066697234808832)]} 0 1
[junit4:junit4] 2> 3472189 T6962 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1438066697249488896)]} 0 2
[junit4:junit4] 2> 3472193 T6925 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[56 (1438066697249488896)]} 0 12
[junit4:junit4] 2> 3472196 T6911 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56]} 0 19
[junit4:junit4] 2> 3472205 T6891 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1438066697271508992)]} 0 2
[junit4:junit4] 2> 3472224 T6958 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1438066697286189056)]} 0 2
[junit4:junit4] 2> 3472227 T6926 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[57 (1438066697286189056)]} 0 11
[junit4:junit4] 2> 3472230 T6912 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57]} 0 19
[junit4:junit4] 2> 3472240 T6892 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1438066697309257728)]} 0 2
[junit4:junit4] 2> 3472258 T6959 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1438066697318694912)]} 0 3
[junit4:junit4] 2> 3472261 T6927 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1438066697318694912)]} 0 13
[junit4:junit4] 2> 3472269 T6888 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1438066697339666432)]} 0 2
[junit4:junit4] 2> 3472282 T6942 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1438066697347006464)]} 0 1
[junit4:junit4] 2> 3472285 T6913 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1438066697347006464)]} 0 10
[junit4:junit4] 2> 3472294 T6889 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1438066697365880832)]} 0 2
[junit4:junit4] 2> 3472315 T6963 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1438066697380560896)]} 0 2
[junit4:junit4] 2> 3472318 T6928 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[60 (1438066697380560896)]} 0 11
[junit4:junit4] 2> 3472321 T6910 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60]} 0 20
[junit4:junit4] 2> 3472331 T6890 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1438066697404678144)]} 0 1
[junit4:junit4] 2> 3472347 T6941 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1438066697415163904)]} 0 2
[junit4:junit4] 2> 3472350 T6909 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1438066697415163904)]} 0 11
[junit4:junit4] 2> 3472359 T6891 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1438066697432989696)]} 0 2
[junit4:junit4] 2> 3472372 T6960 C1524 P53977 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[62 (1438066697445572608)]} 0 0
[junit4:junit4] 2> 3472373 T6930 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[62 (1438066697445572608)]} 0 4
[junit4:junit4] 2> 3472374 T6911 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62]} 0 8
[junit4:junit4] 2> 3472379 T6893 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1438066697455009792)]} 0 1
[junit4:junit4] 2> 3472389 T6944 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[63 (1438066697463398400)]} 0 1
[junit4:junit4] 2> 3472390 T6912 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1438066697463398400)]} 0 5
[junit4:junit4] 2> 3472395 T6892 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1438066697471787008)]} 0 1
[junit4:junit4] 2> 3472407 T6946 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[64 (1438066697478078464)]} 0 1
[junit4:junit4] 2> 3472410 T6913 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1438066697478078464)]} 0 10
[junit4:junit4] 2> 3472416 T6888 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1438066697493807104)]} 0 2
[junit4:junit4] 2> 3472437 T6945 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[65 (1438066697509535744)]} 0 2
[junit4:junit4] 2> 3472440 T6910 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[65 (1438066697509535744)]} 0 11
[junit4:junit4] 2> 3472444 T6925 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65]} 0 21
[junit4:junit4] 2> 3472452 T6889 C1526 P53962 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1438066697531555840)]} 0 2
[junit4:junit4] 2> 3472474 T6942 C1522 P53973 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53967/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[66 (1438066697547284480)]} 0 2
[junit4:junit4] 2> 3472477 T6914 C1523 P53967 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:53970/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[66 (1438066697547284480)]} 0 11
[junit4:junit4] 2> 3472480 T6926 C1525 P53970 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabi
[...truncated too long message...]
] 2> 3507572 T6875 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 3507572 T6875 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:53959 53959
[junit4:junit4] 1> client port:0.0.0.0/0.0.0.0:0
[junit4:junit4] 2> NOTE: reproduce with: ant test -Dtestcase=ChaosMonkeyShardSplitTest -Dtests.method=testDistribSearch -Dtests.seed=8A1CE28C26DBA89F -Dtests.slow=true -Dtests.locale=hr_HR -Dtests.timezone=Pacific/Niue -Dtests.file.encoding=US-ASCII
[junit4:junit4] ERROR 71.3s | ChaosMonkeyShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:53967 returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([8A1CE28C26DBA89F:BFA6C945184C8A3]:0)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
[junit4:junit4] > at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
[junit4:junit4] > at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:228)
[junit4:junit4] > at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
[junit4:junit4] > at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
[junit4:junit4] > at java.lang.Thread.run(Thread.java:722)
[junit4:junit4] 2> 3507596 T6875 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 71275 T6874 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> 3508657 T6967 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 3508658 T6967 oascc.ZkStateReader$2.process A cluster state change: WatchedEvent state:SyncConnected type:NodeChildrenChanged path:/live_nodes, has occurred - updating... (live nodes size: 1)
[junit4:junit4] 2> 3508658 T6967 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Appending, sim=RandomSimilarityProvider(queryNorm=true,coord=yes): {}, locale=hr_HR, timezone=Pacific/Niue
[junit4:junit4] 2> NOTE: Mac OS X 10.8.4 x86_64/Oracle Corporation 1.7.0_21 (64-bit)/cpus=2,threads=2,free=197707888,total=478150656
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SignatureUpdateProcessorFactoryTest, TermVectorComponentTest, TestDFRSimilarityFactory, EchoParamsTest, BasicDistributedZkTest, TestSolrQueryParserDefaultOperatorResource, TestSearchPerf, TestQueryUtils, QueryElevationComponentTest, PingRequestHandlerTest, TestSweetSpotSimilarityFactory, XsltUpdateRequestHandlerTest, NoCacheHeaderTest, TestStressVersions, DistributedTermsComponentTest, DocValuesTest, DateMathParserTest, OpenExchangeRatesOrgProviderTest, QueryEqualityTest, SolrTestCaseJ4Test, CurrencyFieldXmlFileTest, DisMaxRequestHandlerTest, CopyFieldTest, IndexBasedSpellCheckerTest, TestUniqueKeyFieldResource, SolrIndexConfigTest, SpellPossibilityIteratorTest, TestSolrXMLSerializer, SpatialFilterTest, TestIndexingPerformance, TestFieldTypeResource, PreAnalyzedUpdateProcessorTest, UnloadDistributedZkTest, RecoveryZkTest, TestPropInjectDefaults, TestLRUCache, TestDocSet, TestFiltering, TestLazyCores, SuggesterFSTTest, TestSolrIndexConfig, ReturnFieldsTest, TestStressReorder, TestFastLRUCache, ZkControllerTest, TestDynamicFieldResource, ZkSolrClientTest, FullSolrCloudDistribCmdsTest, PrimUtilsTest, TestPerFieldSimilarity, TestFoldingMultitermQuery, MultiTermTest, IndexSchemaTest, ShardRoutingCustomTest, TestDefaultSearchFieldResource, TestManagedSchema, SuggesterWFSTTest, SolrCoreTest, RequestHandlersTest, TestAddFieldRealTimeGet, ConvertedLegacyTest, TestSolrDeletionPolicy2, SolrIndexSplitterTest, TestDefaultSimilarityFactory, TestSchemaSimilarityResource, SortByFunctionTest, TestSchemaVersionResource, TestCSVResponseWriter, BadIndexSchemaTest, TestCloudManagedSchema, DocumentBuilderTest, TestUpdate, PreAnalyzedFieldTest, DistributedQueryElevationComponentTest, LeaderElectionTest, IndexReaderFactoryTest, FieldAnalysisRequestHandlerTest, RegexBoostProcessorTest, DirectUpdateHandlerOptimizeTest, AutoCommitTest, FastVectorHighlighterTest, TestRemoteStreaming, CoreAdminHandlerTest, SolrCmdDistributorTest, DirectSolrSpellCheckerTest, DocValuesMultiTest, SolrCoreCheckLockOnStartupTest, DistanceFunctionTest, TestRangeQuery, TestIBSimilarityFactory, ZkCLITest, CoreContainerCoreInitFailuresTest, OutputWriterTest, PolyFieldTest, PeerSyncTest, SpellingQueryConverterTest, TestCharFilters, DebugComponentTest, JSONWriterTest, DistributedSpellCheckComponentTest, LukeRequestHandlerTest, WordBreakSolrSpellCheckerTest, TestSort, TestCoreDiscovery, UUIDFieldTest, TestSolrDeletionPolicy1, ScriptEngineTest, TestLFUCache, PathHierarchyTokenizerFactoryTest, SoftAutoCommitTest, TestPHPSerializedResponseWriter, HardAutoCommitTest, TestHashPartitioner, SearchHandlerTest, TestSchemaResource, TestComponentsName, TestDistributedSearch, TestSolrXml, TestWordDelimiterFilterFactory, CacheHeaderTest, TestClassNameShortening, SampleTest, PrimitiveFieldTypeTest, TestFastOutputStream, XmlUpdateRequestHandlerTest, BinaryUpdateRequestHandlerTest, TestElisionMultitermQuery, JsonLoaderTest, TestJmxMonitoredMap, DefaultValueUpdateProcessorTest, TestRecovery, BadCopyFieldTest, ChaosMonkeySafeLeaderTest, TestSolrXmlPersistence, TestQueryTypes, CachingDirectoryFactoryTest, TestRealTimeGet, BasicFunctionalityTest, TestSurroundQueryParser, PluginInfoTest, TestDynamicFieldCollectionResource, SolrRequestParserTest, BasicDistributedZk2Test, CollectionsAPIDistributedZkTest, SyncSliceTest, OpenCloseCoreStressTest, OverseerTest, LeaderElectionIntegrationTest, ShardRoutingTest, BasicZkTest, TestReplicationHandler, ClusterStateUpdateTest, TestRandomFaceting, TestZkChroot, TestRandomDVFaceting, SliceStateUpdateTest, TestDistributedGrouping, TestFaceting, TermVectorComponentDistributedTest, TestJoin, TestMultiCoreConfBootstrap, TestReload, TestCoreContainer, SimpleFacetsTest, TestSolr4Spatial, StatsComponentTest, SpellCheckComponentTest, TestGroupingSearch, TestFunctionQuery, DirectUpdateHandlerTest, TestBadConfig, OverseerCollectionProcessorTest, TestIndexSearcher, HighlighterTest, ShowFileRequestHandlerTest, CurrencyFieldOpenExchangeTest, SimplePostToolTest, AnalysisAfterCoreReloadTest, TestExtendedDismaxParser, SpellCheckCollatorTest, SuggesterTSTTest, SuggesterTest, TestStressLucene, TestTrie, TestCSVLoader, SchemaVersionSpecificBehaviorTest, TestPseudoReturnFields, FieldMutatingUpdateProcessorTest, TestAtomicUpdateErrorCases, StatelessScriptUpdateProcessorFactoryTest, SolrInfoMBeanTest, StandardRequestHandlerTest, TestWriterPerf, TestReversedWildcardFilterFactory, DocumentAnalysisRequestHandlerTest, TestOmitPositions, FileBasedSpellCheckerTest, TermsComponentTest, TestValueSourceCache, MoreLikeThisHandlerTest, RequiredFieldsTest, TestSolrQueryParser, TestArbitraryIndexDir, IndexSchemaRuntimeFieldTest, LoggingHandlerTest, SolrPluginUtilsTest, TestJmxIntegration, TestCollationField, UpdateRequestProcessorFactoryTest, MBeansHandlerTest, QueryParsingTest, TestAnalyzedSuggestions, UniqFieldsUpdateProcessorFactoryTest, TestPartialUpdateDeduplication, CSVRequestHandlerTest, TestBinaryResponseWriter, HighlighterConfigTest, SOLR749Test, TestPropInject, TestQuerySenderListener, UpdateParamsTest, AlternateDirectoryTest, TestQuerySenderNoQuery, ResponseLogComponentTest, BadComponentTest, TestStressRecovery, TestMergePolicyConfig, TestBinaryField, NumericFieldsTest, MinimalSchemaTest, TestConfig, TestFuzzyAnalyzedSuggestions, ExternalFileFieldSortTest, TestSolrCoreProperties, TestPostingsSolrHighlighter, DirectSolrConnectionTest, NotRequiredUniqueKeyTest, TestLuceneMatchVersion, TestPhraseSuggestions, TestCodecSupport, SynonymTokenizerTest, TestXIncludeConfig, TestNumberUtils, TestLMDirichletSimilarityFactory, TestLMJelinekMercerSimilarityFactory, TestBM25SimilarityFactory, TestFastWriter, LegacyHTMLStripCharFilterTest, TestPluginEnable, TimeZoneUtilsTest, ResourceLoaderTest, URLClassifyProcessorTest, ChaosMonkeyNothingIsSafeTest, TestSystemIdResolver, TestSuggestSpellingConverter, DateFieldTest, DOMUtilTest, RAMDirectoryFactoryTest, ClusterStateTest, TestSolrJ, TestUtils, TestDocumentBuilder, ZkNodePropsTest, SliceStateTest, SystemInfoHandlerTest, FileUtilsTest, CircularListTest, TestRTGBase, TestCollationKeyRangeQueries, AliasIntegrationTest, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed in 72.57s, 1 test, 1 error <<< FAILURES!
[...truncated 56 lines...]
BUILD FAILED
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:392: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:372: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/build.xml:39: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/build.xml:181: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/solr/common-build.xml:437: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:1246: The following error occurred while executing this line:
/Users/jenkins/jenkins-slave/workspace/Lucene-Solr-4.x-MacOSX/lucene/common-build.xml:890: There were test failures: 298 suites, 1252 tests, 1 error, 19 ignored (7 assumptions)
Total time: 121 minutes 8 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 64bit/jdk1.7.0 -XX:+UseCompressedOops -XX:+UseG1GC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure