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/05/21 05:47:02 UTC
[JENKINS] Lucene-Solr-trunk-Linux (32bit/jdk1.7.0_21) - Build #
5756 - Failure!
Build: http://jenkins.thetaphi.de/job/Lucene-Solr-trunk-Linux/5756/
Java: 32bit/jdk1.7.0_21 -server -XX:+UseSerialGC
1 tests failed.
REGRESSION: org.apache.solr.cloud.ChaosMonkeyShardSplitTest.testDistribSearch
Error Message:
Server at http://127.0.0.1:50624 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:50624 returned non ok status:500, message:Server Error
at __randomizedtesting.SeedInfo.seed([374D61786AE1F316:B6ABEF601DBE932A]:0)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:385)
at org.apache.solr.client.solrj.impl.HttpSolrServer.request(HttpSolrServer.java:180)
at org.apache.solr.cloud.ShardSplitTest.splitShard(ShardSplitTest.java:208)
at org.apache.solr.cloud.ChaosMonkeyShardSplitTest.doTest(ChaosMonkeyShardSplitTest.java:136)
at org.apache.solr.BaseDistributedSearchTestCase.testDistribSearch(BaseDistributedSearchTestCase.java:815)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:57)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:601)
at com.carrotsearch.randomizedtesting.RandomizedRunner.invoke(RandomizedRunner.java:1559)
at com.carrotsearch.randomizedtesting.RandomizedRunner.access$600(RandomizedRunner.java:79)
at com.carrotsearch.randomizedtesting.RandomizedRunner$6.evaluate(RandomizedRunner.java:737)
at com.carrotsearch.randomizedtesting.RandomizedRunner$7.evaluate(RandomizedRunner.java:773)
at com.carrotsearch.randomizedtesting.RandomizedRunner$8.evaluate(RandomizedRunner.java:787)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.TestRuleSetupTeardownChained$1.evaluate(TestRuleSetupTeardownChained.java:50)
at org.apache.lucene.util.TestRuleFieldCacheSanity$1.evaluate(TestRuleFieldCacheSanity.java:51)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at org.apache.lucene.util.TestRuleThreadAndTestName$1.evaluate(TestRuleThreadAndTestName.java:49)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at com.carrotsearch.randomizedtesting.ThreadLeakControl.forkTimeoutingTask(ThreadLeakControl.java:782)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$3.evaluate(ThreadLeakControl.java:442)
at com.carrotsearch.randomizedtesting.RandomizedRunner.runSingleTest(RandomizedRunner.java:746)
at com.carrotsearch.randomizedtesting.RandomizedRunner$3.evaluate(RandomizedRunner.java:648)
at com.carrotsearch.randomizedtesting.RandomizedRunner$4.evaluate(RandomizedRunner.java:682)
at com.carrotsearch.randomizedtesting.RandomizedRunner$5.evaluate(RandomizedRunner.java:693)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesRestoreRule$1.evaluate(SystemPropertiesRestoreRule.java:53)
at org.apache.lucene.util.AbstractBeforeAfterRule$1.evaluate(AbstractBeforeAfterRule.java:46)
at org.apache.lucene.util.TestRuleStoreClassName$1.evaluate(TestRuleStoreClassName.java:42)
at com.carrotsearch.randomizedtesting.rules.SystemPropertiesInvariantRule$1.evaluate(SystemPropertiesInvariantRule.java:55)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.NoShadowingOrOverridesOnMethodsRule$1.evaluate(NoShadowingOrOverridesOnMethodsRule.java:39)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at org.apache.lucene.util.TestRuleAssertionsRequired$1.evaluate(TestRuleAssertionsRequired.java:43)
at org.apache.lucene.util.TestRuleMarkFailure$1.evaluate(TestRuleMarkFailure.java:48)
at org.apache.lucene.util.TestRuleIgnoreAfterMaxFailures$1.evaluate(TestRuleIgnoreAfterMaxFailures.java:70)
at org.apache.lucene.util.TestRuleIgnoreTestSuites$1.evaluate(TestRuleIgnoreTestSuites.java:55)
at com.carrotsearch.randomizedtesting.rules.StatementAdapter.evaluate(StatementAdapter.java:36)
at com.carrotsearch.randomizedtesting.ThreadLeakControl$StatementRunner.run(ThreadLeakControl.java:358)
at java.lang.Thread.run(Thread.java:722)
Build Log:
[...truncated 10109 lines...]
[junit4:junit4] Suite: org.apache.solr.cloud.ChaosMonkeyShardSplitTest
[junit4:junit4] 2> 1168403 T4444 oas.BaseDistributedSearchTestCase.initHostContext Setting hostContext system property: /
[junit4:junit4] 2> 1168408 T4444 oas.SolrTestCaseJ4.setUp ###Starting testDistribSearch
[junit4:junit4] 2> Creating dataDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./solrtest-ChaosMonkeyShardSplitTest-1369107832199
[junit4:junit4] 2> 1168409 T4444 oasc.ZkTestServer.run STARTING ZK TEST SERVER
[junit4:junit4] 2> 1168409 T4445 oasc.ZkTestServer$ZKServerMain.runFromConfig Starting server
[junit4:junit4] 2> 1168509 T4444 oasc.ZkTestServer.run start zk server on port:57974
[junit4:junit4] 2> 1168510 T4444 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1168555 T4451 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@2f8d68 name:ZooKeeperConnection Watcher:127.0.0.1:57974 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1168555 T4444 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1168555 T4444 oascc.SolrZkClient.makePath makePath: /solr
[junit4:junit4] 2> 1168560 T4444 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1168561 T4453 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1796d30 name:ZooKeeperConnection Watcher:127.0.0.1:57974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1168561 T4444 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1168562 T4444 oascc.SolrZkClient.makePath makePath: /collections/collection1
[junit4:junit4] 2> 1168563 T4444 oascc.SolrZkClient.makePath makePath: /collections/collection1/shards
[junit4:junit4] 2> 1168565 T4444 oascc.SolrZkClient.makePath makePath: /collections/control_collection
[junit4:junit4] 2> 1168566 T4444 oascc.SolrZkClient.makePath makePath: /collections/control_collection/shards
[junit4:junit4] 2> 1168568 T4444 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/solrconfig-tlog.xml to /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1168568 T4444 oascc.SolrZkClient.makePath makePath: /configs/conf1/solrconfig.xml
[junit4:junit4] 2> 1168571 T4444 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/schema15.xml to /configs/conf1/schema.xml
[junit4:junit4] 2> 1168572 T4444 oascc.SolrZkClient.makePath makePath: /configs/conf1/schema.xml
[junit4:junit4] 2> 1168575 T4444 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/stopwords.txt to /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1168575 T4444 oascc.SolrZkClient.makePath makePath: /configs/conf1/stopwords.txt
[junit4:junit4] 2> 1168577 T4444 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/protwords.txt to /configs/conf1/protwords.txt
[junit4:junit4] 2> 1168578 T4444 oascc.SolrZkClient.makePath makePath: /configs/conf1/protwords.txt
[junit4:junit4] 2> 1168580 T4444 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/currency.xml to /configs/conf1/currency.xml
[junit4:junit4] 2> 1168580 T4444 oascc.SolrZkClient.makePath makePath: /configs/conf1/currency.xml
[junit4:junit4] 2> 1168583 T4444 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/open-exchange-rates.json to /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1168583 T4444 oascc.SolrZkClient.makePath makePath: /configs/conf1/open-exchange-rates.json
[junit4:junit4] 2> 1168585 T4444 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/mapping-ISOLatin1Accent.txt to /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1168586 T4444 oascc.SolrZkClient.makePath makePath: /configs/conf1/mapping-ISOLatin1Accent.txt
[junit4:junit4] 2> 1168587 T4444 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/old_synonyms.txt to /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1168588 T4444 oascc.SolrZkClient.makePath makePath: /configs/conf1/old_synonyms.txt
[junit4:junit4] 2> 1168590 T4444 oasc.AbstractZkTestCase.putConfig put /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test-files/solr/collection1/conf/synonyms.txt to /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1168590 T4444 oascc.SolrZkClient.makePath makePath: /configs/conf1/synonyms.txt
[junit4:junit4] 2> 1168691 T4444 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1168763 T4444 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:54981
[junit4:junit4] 2> 1168763 T4444 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1168764 T4444 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1168764 T4444 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369107832382
[junit4:junit4] 2> 1168764 T4444 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369107832382/solr.xml
[junit4:junit4] 2> 1168765 T4444 oasc.CoreContainer.<init> New CoreContainer 20869081
[junit4:junit4] 2> 1168765 T4444 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369107832382/'
[junit4:junit4] 2> 1168765 T4444 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369107832382/'
[junit4:junit4] 2> 1168817 T4444 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1168818 T4444 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1168818 T4444 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1168818 T4444 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1168819 T4444 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1168819 T4444 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1168819 T4444 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1168820 T4444 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1168820 T4444 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1168820 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1168886 T4444 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1168887 T4444 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57974/solr
[junit4:junit4] 2> 1168888 T4444 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1168889 T4444 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1168890 T4464 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@4ddae name:ZooKeeperConnection Watcher:127.0.0.1:57974 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1168890 T4444 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1168891 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1168894 T4444 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1168896 T4466 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@425679 name:ZooKeeperConnection Watcher:127.0.0.1:57974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1168896 T4444 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1168897 T4444 oascc.SolrZkClient.makePath makePath: /overseer/queue
[junit4:junit4] 2> 1168899 T4444 oascc.SolrZkClient.makePath makePath: /overseer/collection-queue-work
[junit4:junit4] 2> 1168901 T4444 oascc.SolrZkClient.makePath makePath: /live_nodes
[junit4:junit4] 2> 1168902 T4444 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:54981_
[junit4:junit4] 2> 1168904 T4444 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:54981_
[junit4:junit4] 2> 1168906 T4444 oascc.SolrZkClient.makePath makePath: /overseer_elect/election
[junit4:junit4] 2> 1168909 T4444 oascc.SolrZkClient.makePath makePath: /overseer_elect/leader
[junit4:junit4] 2> 1168910 T4444 oasc.Overseer.start Overseer (id=89725850891190275-127.0.0.1:54981_-n_0000000000) starting
[junit4:junit4] 2> 1168912 T4444 oascc.SolrZkClient.makePath makePath: /overseer/queue-work
[junit4:junit4] 2> 1168915 T4444 oascc.SolrZkClient.makePath makePath: /clusterstate.json
[junit4:junit4] 2> 1168915 T4468 oasc.OverseerCollectionProcessor.run Process current queue of collection creations
[junit4:junit4] 2> 1168916 T4444 oascc.SolrZkClient.makePath makePath: /aliases.json
[junit4:junit4] 2> 1168917 T4444 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1168919 T4467 oasc.Overseer$ClusterStateUpdater.run Starting to work on the main queue
[junit4:junit4] 2> 1168922 T4469 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369107832382/collection1
[junit4:junit4] 2> 1168922 T4469 oasc.ZkController.createCollectionZkNode Check for collection zkNode:control_collection
[junit4:junit4] 2> 1168922 T4469 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1168922 T4469 oasc.ZkController.readConfigName Load collection config from:/collections/control_collection
[junit4:junit4] 2> 1168923 T4469 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369107832382/collection1/'
[junit4:junit4] 2> 1168924 T4469 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369107832382/collection1/lib/README' to classloader
[junit4:junit4] 2> 1168924 T4469 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369107832382/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1168946 T4469 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1168974 T4469 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1168975 T4469 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1168979 T4469 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1169268 T4469 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1169270 T4469 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1169271 T4469 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1169274 T4469 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1169289 T4469 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1169289 T4469 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-controljetty-1369107832382/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/control/data/
[junit4:junit4] 2> 1169290 T4469 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a52c57
[junit4:junit4] 2> 1169290 T4469 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1169291 T4469 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/control/data
[junit4:junit4] 2> 1169291 T4469 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/control/data/index/
[junit4:junit4] 2> 1169291 T4469 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/control/data/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1169291 T4469 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/control/data/index
[junit4:junit4] 2> 1169293 T4469 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4643fd lockFactory=org.apache.lucene.store.NativeFSLockFactory@165d06b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1169293 T4469 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1169294 T4469 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1169295 T4469 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1169295 T4469 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1169296 T4469 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1169296 T4469 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1169296 T4469 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1169296 T4469 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1169297 T4469 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1169297 T4469 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1169299 T4469 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1169301 T4469 oass.SolrIndexSearcher.<init> Opening Searcher@1e1fb19 main
[junit4:junit4] 2> 1169302 T4469 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/control/data/tlog
[junit4:junit4] 2> 1169302 T4469 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1169302 T4469 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1169305 T4470 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1e1fb19 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1169306 T4469 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1169306 T4469 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1170421 T4467 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1170421 T4467 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:54981_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54981"}
[junit4:junit4] 2> 1170422 T4467 oasc.Overseer$ClusterStateUpdater.createCollection Create collection control_collection with numShards 1
[junit4:junit4] 2> 1170422 T4467 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1170424 T4466 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> 1171308 T4469 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1171309 T4469 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:54981 collection:control_collection shard:shard1
[junit4:junit4] 2> 1171310 T4469 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leader_elect/shard1/election
[junit4:junit4] 2> 1171329 T4469 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1171331 T4469 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1171331 T4469 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1171331 T4469 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:54981/collection1/
[junit4:junit4] 2> 1171331 T4469 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1171331 T4469 oasc.SyncStrategy.syncToMe http://127.0.0.1:54981/collection1/ has no replicas
[junit4:junit4] 2> 1171332 T4469 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:54981/collection1/
[junit4:junit4] 2> 1171332 T4469 oascc.SolrZkClient.makePath makePath: /collections/control_collection/leaders/shard1
[junit4:junit4] 2> 1171927 T4467 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1171931 T4466 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> 1171937 T4469 oasc.ZkController.register We are http://127.0.0.1:54981/collection1/ and leader is http://127.0.0.1:54981/collection1/
[junit4:junit4] 2> 1171937 T4469 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:54981
[junit4:junit4] 2> 1171938 T4469 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1171938 T4469 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1171938 T4469 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1171939 T4469 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1171940 T4444 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1171940 T4444 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1171940 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1171943 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:
[junit4:junit4] 2> 1171944 T4444 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1171945 T4473 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1b046e5 name:ZooKeeperConnection Watcher:127.0.0.1:57974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1171945 T4444 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1171946 T4444 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1171948 T4444 oasc.ChaosMonkey.monkeyLog monkey: init - expire sessions:true cause connection loss:true
[junit4:junit4] 2> 1172003 T4444 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1172006 T4444 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:50624
[junit4:junit4] 2> 1172007 T4444 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1172007 T4444 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1172008 T4444 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369107835738
[junit4:junit4] 2> 1172008 T4444 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369107835738/solr.xml
[junit4:junit4] 2> 1172008 T4444 oasc.CoreContainer.<init> New CoreContainer 3891062
[junit4:junit4] 2> 1172009 T4444 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369107835738/'
[junit4:junit4] 2> 1172009 T4444 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369107835738/'
[junit4:junit4] 2> 1172046 T4444 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1172047 T4444 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1172047 T4444 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1172047 T4444 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1172047 T4444 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1172048 T4444 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1172048 T4444 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1172048 T4444 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1172049 T4444 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1172049 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1172052 T4444 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1172052 T4444 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57974/solr
[junit4:junit4] 2> 1172053 T4444 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1172054 T4444 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1172056 T4484 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@8a374b name:ZooKeeperConnection Watcher:127.0.0.1:57974 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1172056 T4444 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1172057 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1172060 T4444 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1172060 T4486 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@da9dc name:ZooKeeperConnection Watcher:127.0.0.1:57974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1172061 T4444 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1172063 T4444 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1173065 T4444 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:50624_
[junit4:junit4] 2> 1173066 T4444 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:50624_
[junit4:junit4] 2> 1173067 T4466 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> 1173068 T4473 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1173068 T4486 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1173068 T4466 oascc.ZkStateReader$3.process Updating live nodes... (2)
[junit4:junit4] 2> 1173071 T4487 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369107835738/collection1
[junit4:junit4] 2> 1173072 T4487 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1173072 T4487 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1173072 T4487 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1173073 T4487 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369107835738/collection1/'
[junit4:junit4] 2> 1173074 T4487 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369107835738/collection1/lib/README' to classloader
[junit4:junit4] 2> 1173074 T4487 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369107835738/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1173098 T4487 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1173140 T4487 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1173141 T4487 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1173145 T4487 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1173435 T4467 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1173435 T4467 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=1 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:54981__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:54981_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:54981"}
[junit4:junit4] 2> 1173437 T4487 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1173438 T4466 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> 1173438 T4473 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> 1173438 T4486 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> 1173439 T4487 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1173441 T4487 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1173443 T4487 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1173458 T4487 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1173458 T4487 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty1-1369107835738/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty1/
[junit4:junit4] 2> 1173458 T4487 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a52c57
[junit4:junit4] 2> 1173459 T4487 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1173459 T4487 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty1
[junit4:junit4] 2> 1173459 T4487 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty1/index/
[junit4:junit4] 2> 1173459 T4487 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty1/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1173460 T4487 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty1/index
[junit4:junit4] 2> 1173461 T4487 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3e8674 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a4cf80),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1173461 T4487 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1173463 T4487 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1173463 T4487 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1173463 T4487 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1173464 T4487 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1173464 T4487 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1173464 T4487 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1173464 T4487 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1173465 T4487 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1173465 T4487 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1173467 T4487 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1173469 T4487 oass.SolrIndexSearcher.<init> Opening Searcher@19f6497 main
[junit4:junit4] 2> 1173470 T4487 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty1/tlog
[junit4:junit4] 2> 1173470 T4487 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1173470 T4487 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1173473 T4488 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@19f6497 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1173474 T4487 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1173474 T4487 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1174940 T4467 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1174941 T4467 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:50624_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50624"}
[junit4:junit4] 2> 1174941 T4467 oasc.Overseer$ClusterStateUpdater.createCollection Create collection collection1 with numShards 2
[junit4:junit4] 2> 1174941 T4467 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1174945 T4466 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> 1174945 T4473 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> 1174945 T4486 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> 1175476 T4487 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1175477 T4487 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:50624 collection:collection1 shard:shard1
[junit4:junit4] 2> 1175477 T4487 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard1/election
[junit4:junit4] 2> 1175482 T4487 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1175484 T4487 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1175484 T4487 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1175484 T4487 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:50624/collection1/
[junit4:junit4] 2> 1175484 T4487 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1175485 T4487 oasc.SyncStrategy.syncToMe http://127.0.0.1:50624/collection1/ has no replicas
[junit4:junit4] 2> 1175485 T4487 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:50624/collection1/
[junit4:junit4] 2> 1175485 T4487 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard1
[junit4:junit4] 2> 1176448 T4467 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1176452 T4466 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> 1176452 T4473 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> 1176452 T4486 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> 1176491 T4487 oasc.ZkController.register We are http://127.0.0.1:50624/collection1/ and leader is http://127.0.0.1:50624/collection1/
[junit4:junit4] 2> 1176492 T4487 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:50624
[junit4:junit4] 2> 1176492 T4487 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1176492 T4487 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1176492 T4487 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1176494 T4487 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1176495 T4444 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1176496 T4444 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1176496 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1176557 T4444 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1176560 T4444 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:47652
[junit4:junit4] 2> 1176561 T4444 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1176561 T4444 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1176561 T4444 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369107840289
[junit4:junit4] 2> 1176562 T4444 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369107840289/solr.xml
[junit4:junit4] 2> 1176562 T4444 oasc.CoreContainer.<init> New CoreContainer 12487318
[junit4:junit4] 2> 1176562 T4444 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369107840289/'
[junit4:junit4] 2> 1176563 T4444 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369107840289/'
[junit4:junit4] 2> 1176603 T4444 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1176603 T4444 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1176604 T4444 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1176604 T4444 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1176604 T4444 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1176605 T4444 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1176605 T4444 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1176606 T4444 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1176606 T4444 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1176606 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1176609 T4444 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1176610 T4444 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57974/solr
[junit4:junit4] 2> 1176610 T4444 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1176611 T4444 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1176612 T4500 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@145b5d1 name:ZooKeeperConnection Watcher:127.0.0.1:57974 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1176612 T4444 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1176613 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1176617 T4444 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1176618 T4502 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1aab9a5 name:ZooKeeperConnection Watcher:127.0.0.1:57974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1176618 T4444 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1176620 T4444 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1177622 T4444 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:47652_
[junit4:junit4] 2> 1177623 T4444 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:47652_
[junit4:junit4] 2> 1177625 T4486 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> 1177625 T4473 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> 1177626 T4502 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1177626 T4486 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1177627 T4473 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1177625 T4466 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> 1177630 T4466 oascc.ZkStateReader$3.process Updating live nodes... (3)
[junit4:junit4] 2> 1177630 T4503 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369107840289/collection1
[junit4:junit4] 2> 1177631 T4503 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1177631 T4503 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1177631 T4503 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1177632 T4503 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369107840289/collection1/'
[junit4:junit4] 2> 1177633 T4503 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369107840289/collection1/lib/README' to classloader
[junit4:junit4] 2> 1177634 T4503 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369107840289/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1177682 T4503 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1177709 T4503 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1177711 T4503 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1177714 T4503 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1177956 T4467 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1177957 T4467 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:50624__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:50624_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:50624"}
[junit4:junit4] 2> 1177960 T4473 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> 1177960 T4502 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> 1177960 T4486 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> 1177960 T4466 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> 1178094 T4503 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1178096 T4503 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1178098 T4503 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1178100 T4503 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1178121 T4503 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1178122 T4503 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty2-1369107840289/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty2/
[junit4:junit4] 2> 1178122 T4503 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a52c57
[junit4:junit4] 2> 1178122 T4503 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1178123 T4503 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty2
[junit4:junit4] 2> 1178123 T4503 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty2/index/
[junit4:junit4] 2> 1178123 T4503 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty2/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1178123 T4503 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty2/index
[junit4:junit4] 2> 1178125 T4503 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@113aed5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@19b3118),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1178125 T4503 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1178127 T4503 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1178127 T4503 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1178128 T4503 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1178128 T4503 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1178129 T4503 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1178129 T4503 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1178129 T4503 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1178130 T4503 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1178130 T4503 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1178132 T4503 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1178135 T4503 oass.SolrIndexSearcher.<init> Opening Searcher@141f39 main
[junit4:junit4] 2> 1178135 T4503 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty2/tlog
[junit4:junit4] 2> 1178136 T4503 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1178136 T4503 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1178140 T4504 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@141f39 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1178141 T4503 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1178141 T4503 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1179464 T4467 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1179465 T4467 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:47652_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47652"}
[junit4:junit4] 2> 1179465 T4467 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1179465 T4467 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1179513 T4486 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> 1179513 T4473 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> 1179513 T4466 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> 1179513 T4502 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> 1180144 T4503 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1180145 T4503 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:47652 collection:collection1 shard:shard2
[junit4:junit4] 2> 1180145 T4503 oascc.SolrZkClient.makePath makePath: /collections/collection1/leader_elect/shard2/election
[junit4:junit4] 2> 1180150 T4503 oasc.ShardLeaderElectionContext.runLeaderProcess Running the leader process.
[junit4:junit4] 2> 1180151 T4503 oasc.ShardLeaderElectionContext.waitForReplicasToComeUp Enough replicas found to continue.
[junit4:junit4] 2> 1180151 T4503 oasc.ShardLeaderElectionContext.runLeaderProcess I may be the new leader - try and sync
[junit4:junit4] 2> 1180152 T4503 oasc.SyncStrategy.sync Sync replicas to http://127.0.0.1:47652/collection1/
[junit4:junit4] 2> 1180152 T4503 oasc.SyncStrategy.syncReplicas Sync Success - now sync replicas to me
[junit4:junit4] 2> 1180152 T4503 oasc.SyncStrategy.syncToMe http://127.0.0.1:47652/collection1/ has no replicas
[junit4:junit4] 2> 1180152 T4503 oasc.ShardLeaderElectionContext.runLeaderProcess I am the new leader: http://127.0.0.1:47652/collection1/
[junit4:junit4] 2> 1180153 T4503 oascc.SolrZkClient.makePath makePath: /collections/collection1/leaders/shard2
[junit4:junit4] 2> 1181018 T4467 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1181022 T4486 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> 1181022 T4502 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> 1181022 T4473 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> 1181022 T4466 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> 1181058 T4503 oasc.ZkController.register We are http://127.0.0.1:47652/collection1/ and leader is http://127.0.0.1:47652/collection1/
[junit4:junit4] 2> 1181059 T4503 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:47652
[junit4:junit4] 2> 1181059 T4503 oasc.ZkController.checkRecovery I am the leader, no recovery necessary
[junit4:junit4] 2> 1181059 T4503 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1181059 T4503 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1181061 T4503 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1181062 T4444 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1181062 T4444 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1181063 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1181126 T4444 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1181129 T4444 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:45691
[junit4:junit4] 2> 1181129 T4444 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1181130 T4444 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1181130 T4444 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369107844856
[junit4:junit4] 2> 1181131 T4444 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369107844856/solr.xml
[junit4:junit4] 2> 1181131 T4444 oasc.CoreContainer.<init> New CoreContainer 1859448
[junit4:junit4] 2> 1181131 T4444 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369107844856/'
[junit4:junit4] 2> 1181132 T4444 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369107844856/'
[junit4:junit4] 2> 1181188 T4444 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1181188 T4444 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1181188 T4444 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1181189 T4444 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1181189 T4444 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1181190 T4444 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1181190 T4444 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1181190 T4444 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1181191 T4444 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1181191 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1181194 T4444 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1181194 T4444 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57974/solr
[junit4:junit4] 2> 1181195 T4444 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1181196 T4444 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1181198 T4516 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@d55f7a name:ZooKeeperConnection Watcher:127.0.0.1:57974 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1181198 T4444 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1181199 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1181202 T4444 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1181203 T4518 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@51c7ba name:ZooKeeperConnection Watcher:127.0.0.1:57974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1181204 T4444 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1181206 T4444 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1182208 T4444 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:45691_
[junit4:junit4] 2> 1182210 T4444 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:45691_
[junit4:junit4] 2> 1182211 T4502 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> 1182211 T4473 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> 1182212 T4466 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> 1182211 T4486 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> 1182212 T4518 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1182213 T4502 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1182213 T4473 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1182213 T4466 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1182214 T4486 oascc.ZkStateReader$3.process Updating live nodes... (4)
[junit4:junit4] 2> 1182216 T4519 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369107844856/collection1
[junit4:junit4] 2> 1182216 T4519 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1182217 T4519 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1182217 T4519 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1182217 T4519 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369107844856/collection1/'
[junit4:junit4] 2> 1182218 T4519 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369107844856/collection1/lib/README' to classloader
[junit4:junit4] 2> 1182218 T4519 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369107844856/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1182241 T4519 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1182270 T4519 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1182272 T4519 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1182275 T4519 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1182525 T4467 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1182526 T4467 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:47652__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:47652_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:47652"}
[junit4:junit4] 2> 1182540 T4502 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> 1182541 T4486 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> 1182541 T4518 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> 1182541 T4473 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> 1182541 T4466 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> 1182626 T4519 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1182628 T4519 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1182629 T4519 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1182632 T4519 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1182652 T4519 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1182652 T4519 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty3-1369107844856/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty3/
[junit4:junit4] 2> 1182652 T4519 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a52c57
[junit4:junit4] 2> 1182653 T4519 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1182653 T4519 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty3
[junit4:junit4] 2> 1182653 T4519 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty3/index/
[junit4:junit4] 2> 1182653 T4519 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty3/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1182654 T4519 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty3/index
[junit4:junit4] 2> 1182655 T4519 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d51aca lockFactory=org.apache.lucene.store.NativeFSLockFactory@c84ba8),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1182655 T4519 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1182657 T4519 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1182657 T4519 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1182658 T4519 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1182658 T4519 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1182659 T4519 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1182659 T4519 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1182659 T4519 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1182659 T4519 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1182660 T4519 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1182662 T4519 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1182664 T4519 oass.SolrIndexSearcher.<init> Opening Searcher@4e9dc main
[junit4:junit4] 2> 1182664 T4519 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty3/tlog
[junit4:junit4] 2> 1182665 T4519 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1182665 T4519 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1182668 T4520 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@4e9dc main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1182669 T4519 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1182669 T4519 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1184045 T4467 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1184045 T4467 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:45691_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45691"}
[junit4:junit4] 2> 1184046 T4467 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1184046 T4467 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard1
[junit4:junit4] 2> 1184063 T4518 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> 1184063 T4473 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> 1184063 T4466 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> 1184063 T4502 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> 1184063 T4486 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> 1184670 T4519 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1184671 T4519 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:45691 collection:collection1 shard:shard1
[junit4:junit4] 2> 1184673 T4519 oasc.ZkController.register We are http://127.0.0.1:45691/collection1/ and leader is http://127.0.0.1:50624/collection1/
[junit4:junit4] 2> 1184673 T4519 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:45691
[junit4:junit4] 2> 1184674 T4519 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1184674 T4519 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C214 name=collection1 org.apache.solr.core.SolrCore@1378b89 url=http://127.0.0.1:45691/collection1 node=127.0.0.1:45691_ C214_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:45691_, base_url=http://127.0.0.1:45691}
[junit4:junit4] 2> 1184674 T4521 C214 P45691 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1184675 T4519 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1184676 T4521 C214 P45691 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1184676 T4521 C214 P45691 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1184676 T4521 C214 P45691 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1184677 T4444 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1184677 T4444 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1184677 T4521 C214 P45691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1184678 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1184684 T4479 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:45691__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1184740 T4444 oejs.Server.doStart jetty-8.1.10.v20130312
[junit4:junit4] 2> 1184742 T4444 oejs.AbstractConnector.doStart Started SelectChannelConnector@127.0.0.1:40528
[junit4:junit4] 2> 1184743 T4444 oass.SolrDispatchFilter.init SolrDispatchFilter.init()
[junit4:junit4] 2> 1184743 T4444 oasc.SolrResourceLoader.locateSolrHome JNDI not configured for solr (NoInitialContextEx)
[junit4:junit4] 2> 1184744 T4444 oasc.SolrResourceLoader.locateSolrHome using system property solr.solr.home: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369107848471
[junit4:junit4] 2> 1184744 T4444 oasc.CoreContainer$Initializer.initialize looking for solr config file: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369107848471/solr.xml
[junit4:junit4] 2> 1184744 T4444 oasc.CoreContainer.<init> New CoreContainer 22713164
[junit4:junit4] 2> 1184745 T4444 oasc.CoreContainer.load Loading CoreContainer using Solr Home: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369107848471/'
[junit4:junit4] 2> 1184745 T4444 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369107848471/'
[junit4:junit4] 2> 1184784 T4444 oashc.HttpShardHandlerFactory.getParameter Setting socketTimeout to: 120000
[junit4:junit4] 2> 1184784 T4444 oashc.HttpShardHandlerFactory.getParameter Setting urlScheme to: http://
[junit4:junit4] 2> 1184784 T4444 oashc.HttpShardHandlerFactory.getParameter Setting connTimeout to: 15000
[junit4:junit4] 2> 1184785 T4444 oashc.HttpShardHandlerFactory.getParameter Setting maxConnectionsPerHost to: 20
[junit4:junit4] 2> 1184785 T4444 oashc.HttpShardHandlerFactory.getParameter Setting corePoolSize to: 0
[junit4:junit4] 2> 1184785 T4444 oashc.HttpShardHandlerFactory.getParameter Setting maximumPoolSize to: 2147483647
[junit4:junit4] 2> 1184786 T4444 oashc.HttpShardHandlerFactory.getParameter Setting maxThreadIdleTime to: 5
[junit4:junit4] 2> 1184786 T4444 oashc.HttpShardHandlerFactory.getParameter Setting sizeOfQueue to: -1
[junit4:junit4] 2> 1184786 T4444 oashc.HttpShardHandlerFactory.getParameter Setting fairnessPolicy to: false
[junit4:junit4] 2> 1184787 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnectionsPerHost=20&maxConnections=10000&socketTimeout=120000&connTimeout=15000&retry=false
[junit4:junit4] 2> 1184789 T4444 oasl.LogWatcher.newRegisteredLogWatcher Registering Log Listener
[junit4:junit4] 2> 1184790 T4444 oasc.ZkContainer.initZooKeeper Zookeeper client=127.0.0.1:57974/solr
[junit4:junit4] 2> 1184790 T4444 oasc.ZkController.checkChrootPath zkHost includes chroot
[junit4:junit4] 2> 1184792 T4444 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1184793 T4533 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@13377b1 name:ZooKeeperConnection Watcher:127.0.0.1:57974 got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1184793 T4444 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1184795 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=500&maxConnectionsPerHost=16&socketTimeout=120000&connTimeout=15000
[junit4:junit4] 2> 1184799 T4444 oascc.ConnectionManager.waitForConnected Waiting for client to connect to ZooKeeper
[junit4:junit4] 2> 1184800 T4535 oascc.ConnectionManager.process Watcher org.apache.solr.common.cloud.ConnectionManager@1d9f704 name:ZooKeeperConnection Watcher:127.0.0.1:57974/solr got event WatchedEvent state:SyncConnected type:None path:null path:null type:None
[junit4:junit4] 2> 1184800 T4444 oascc.ConnectionManager.waitForConnected Client is connected to ZooKeeper
[junit4:junit4] 2> 1184803 T4444 oascc.ZkStateReader.createClusterStateWatchersAndUpdate Updating cluster state from ZooKeeper...
[junit4:junit4] 2> 1185584 T4467 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1185584 T4467 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:45691__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:45691_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45691"}
[junit4:junit4] 2> 1185643 T4466 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> 1185643 T4473 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> 1185643 T4486 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> 1185643 T4518 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> 1185643 T4502 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> 1185643 T4535 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> 1185685 T4479 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:45691__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 1 seconds.
[junit4:junit4] 2> 1185686 T4479 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:45691__collection1&state=recovering&nodeName=127.0.0.1:45691_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=1002
[junit4:junit4] 2> 1185805 T4444 oasc.ZkController.createEphemeralLiveNode Register node as live in ZooKeeper:/live_nodes/127.0.0.1:40528_
[junit4:junit4] 2> 1185807 T4444 oascc.SolrZkClient.makePath makePath: /live_nodes/127.0.0.1:40528_
[junit4:junit4] 2> 1185809 T4486 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> 1185809 T4518 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> 1185809 T4502 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> 1185809 T4473 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> 1185809 T4535 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> 1185809 T4466 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> 1185811 T4486 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1185811 T4518 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1185811 T4473 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1185811 T4502 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1185812 T4466 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1185812 T4535 oascc.ZkStateReader$3.process Updating live nodes... (5)
[junit4:junit4] 2> 1185814 T4536 oasc.CoreContainer.create Creating SolrCore 'collection1' using instanceDir: /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369107848471/collection1
[junit4:junit4] 2> 1185814 T4536 oasc.ZkController.createCollectionZkNode Check for collection zkNode:collection1
[junit4:junit4] 2> 1185815 T4536 oasc.ZkController.createCollectionZkNode Collection zkNode exists
[junit4:junit4] 2> 1185815 T4536 oasc.ZkController.readConfigName Load collection config from:/collections/collection1
[junit4:junit4] 2> 1185816 T4536 oasc.SolrResourceLoader.<init> new SolrResourceLoader for directory: '/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369107848471/collection1/'
[junit4:junit4] 2> 1185816 T4536 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369107848471/collection1/lib/README' to classloader
[junit4:junit4] 2> 1185817 T4536 oasc.SolrResourceLoader.replaceClassLoader Adding 'file:/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369107848471/collection1/lib/classes/' to classloader
[junit4:junit4] 2> 1185840 T4536 oasc.SolrConfig.<init> Using Lucene MatchVersion: LUCENE_50
[junit4:junit4] 2> 1185887 T4536 oasc.SolrConfig.<init> Loaded SolrConfig: solrconfig.xml
[junit4:junit4] 2> 1185888 T4536 oass.IndexSchema.readSchema Reading Solr Schema from schema.xml
[junit4:junit4] 2> 1185892 T4536 oass.IndexSchema.readSchema [collection1] Schema name=test
[junit4:junit4] 2> 1186191 T4536 oass.IndexSchema.readSchema default search field in schema is text
[junit4:junit4] 2> 1186193 T4536 oass.IndexSchema.readSchema unique key field: id
[junit4:junit4] 2> 1186195 T4536 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1186198 T4536 oass.FileExchangeRateProvider.reload Reloading exchange rates from file currency.xml
[junit4:junit4] 2> 1186216 T4536 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1186216 T4536 oasc.SolrCore.<init> [collection1] Opening new SolrCore at /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-jetty4-1369107848471/collection1/, dataDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4/
[junit4:junit4] 2> 1186216 T4536 oasc.JmxMonitoredMap.<init> JMX monitoring is enabled. Adding Solr mbeans to JMX Server: com.sun.jmx.mbeanserver.JmxMBeanServer@a52c57
[junit4:junit4] 2> 1186217 T4536 oasc.SolrCore.initDirectoryFactory org.apache.solr.core.MockDirectoryFactory
[junit4:junit4] 2> 1186217 T4536 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4
[junit4:junit4] 2> 1186217 T4536 oasc.SolrCore.getNewIndexDir New index directory detected: old=null new=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4/index/
[junit4:junit4] 2> 1186218 T4536 oasc.SolrCore.initIndex WARN [collection1] Solr index directory './org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4/index' doesn't exist. Creating new index...
[junit4:junit4] 2> 1186218 T4536 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4/index
[junit4:junit4] 2> 1186220 T4536 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@14d4729 lockFactory=org.apache.lucene.store.NativeFSLockFactory@11fb59a),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1186221 T4536 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1186222 T4536 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "dedupe"
[junit4:junit4] 2> 1186223 T4536 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "stored_sig"
[junit4:junit4] 2> 1186223 T4536 oasup.UpdateRequestProcessorChain.init inserting DistributedUpdateProcessorFactory into updateRequestProcessorChain "distrib-dup-test-chain-implicit"
[junit4:junit4] 2> 1186224 T4536 oasc.RequestHandlers.initHandlersFromConfig created standard: solr.StandardRequestHandler
[junit4:junit4] 2> 1186224 T4536 oasc.RequestHandlers.initHandlersFromConfig created /get: solr.RealTimeGetHandler
[junit4:junit4] 2> 1186225 T4536 oasc.RequestHandlers.initHandlersFromConfig adding lazy requestHandler: solr.ReplicationHandler
[junit4:junit4] 2> 1186225 T4536 oasc.RequestHandlers.initHandlersFromConfig created /replication: solr.ReplicationHandler
[junit4:junit4] 2> 1186225 T4536 oasc.RequestHandlers.initHandlersFromConfig created /update: solr.UpdateRequestHandler
[junit4:junit4] 2> 1186226 T4536 oasc.RequestHandlers.initHandlersFromConfig created /admin/: org.apache.solr.handler.admin.AdminHandlers
[junit4:junit4] 2> 1186229 T4536 oashl.XMLLoader.init xsltCacheLifetimeSeconds=60
[junit4:junit4] 2> 1186231 T4536 oass.SolrIndexSearcher.<init> Opening Searcher@1a09614 main
[junit4:junit4] 2> 1186231 T4536 oasu.UpdateHandler.clearLog Clearing tlog files, tlogDir=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4/tlog
[junit4:junit4] 2> 1186232 T4536 oasu.CommitTracker.<init> Hard AutoCommit: disabled
[junit4:junit4] 2> 1186232 T4536 oasu.CommitTracker.<init> Soft AutoCommit: disabled
[junit4:junit4] 2> 1186235 T4537 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1a09614 main{StandardDirectoryReader(segments_1:1)}
[junit4:junit4] 2> 1186236 T4536 oasc.ZkController.publish publishing core=collection1 state=down
[junit4:junit4] 2> 1186236 T4536 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1187148 T4467 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1187149 T4467 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:40528_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40528"}
[junit4:junit4] 2> 1187149 T4467 oasc.Overseer$ClusterStateUpdater.updateState Collection already exists with numShards=2
[junit4:junit4] 2> 1187149 T4467 oasc.Overseer$ClusterStateUpdater.updateState Assigning new node to shard=shard2
[junit4:junit4] 2> 1187156 T4486 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> 1187156 T4518 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> 1187156 T4473 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> 1187156 T4502 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> 1187156 T4535 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> 1187156 T4466 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> 1187238 T4536 oasc.CoreContainer.registerCore registering core: collection1
[junit4:junit4] 2> 1187239 T4536 oasc.ZkController.register Register replica - core:collection1 address:http://127.0.0.1:40528 collection:collection1 shard:shard2
[junit4:junit4] 2> 1187241 T4536 oasc.ZkController.register We are http://127.0.0.1:40528/collection1/ and leader is http://127.0.0.1:47652/collection1/
[junit4:junit4] 2> 1187241 T4536 oasc.ZkController.register No LogReplay needed for core=collection1 baseURL=http://127.0.0.1:40528
[junit4:junit4] 2> 1187241 T4536 oasc.ZkController.checkRecovery Core needs to recover:collection1
[junit4:junit4] 2> 1187241 T4536 oasu.DefaultSolrCoreState.doRecovery Running recovery - first canceling any ongoing recovery
[junit4:junit4] 2> ASYNC NEW_CORE C215 name=collection1 org.apache.solr.core.SolrCore@1e5c724 url=http://127.0.0.1:40528/collection1 node=127.0.0.1:40528_ C215_STATE=coll:collection1 core:collection1 props:{state=down, core=collection1, collection=collection1, node_name=127.0.0.1:40528_, base_url=http://127.0.0.1:40528}
[junit4:junit4] 2> 1187242 T4538 C215 P40528 oasc.RecoveryStrategy.run Starting recovery process. core=collection1 recoveringAfterStartup=true
[junit4:junit4] 2> 1187242 T4536 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1187243 T4538 C215 P40528 oasc.RecoveryStrategy.doRecovery ###### startupVersions=[]
[junit4:junit4] 2> 1187243 T4538 C215 P40528 oasc.ZkController.publish publishing core=collection1 state=recovering
[junit4:junit4] 2> 1187243 T4538 C215 P40528 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1187243 T4444 oass.SolrDispatchFilter.init user.dir=/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0
[junit4:junit4] 2> 1187244 T4444 oass.SolrDispatchFilter.init SolrDispatchFilter.init() done
[junit4:junit4] 2> 1187244 T4538 C215 P40528 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1187244 T4444 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1187247 T4444 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1187248 T4498 oasha.CoreAdminHandler.handleWaitForStateAction Going to wait for coreNodeName: 127.0.0.1:40528__collection1, state: recovering, checkLive: true, onlyIfLeader: true
[junit4:junit4] 2> 1187248 T4444 oasc.AbstractFullDistribZkTestBase.waitForThingsToLevelOut Wait for recoveries to finish - wait 15 for each attempt
[junit4:junit4] 2> 1187249 T4444 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Wait for recoveries to finish - collection: collection1 failOnTimeout:true timeout (sec):15
[junit4:junit4] 2> 1187249 T4444 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C214_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:45691_, base_url=http://127.0.0.1:45691}
[junit4:junit4] 2> 1187686 T4521 C214 P45691 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:50624/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1187687 T4521 C214 P45691 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:45691 START replicas=[http://127.0.0.1:50624/collection1/] nUpdates=100
[junit4:junit4] 2> 1187687 T4521 C214 P45691 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1187687 T4521 C214 P45691 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1187687 T4521 C214 P45691 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1187688 T4521 C214 P45691 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1187688 T4521 C214 P45691 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1187688 T4521 C214 P45691 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:50624/collection1/. core=collection1
[junit4:junit4] 2> 1187688 T4521 C214 P45691 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> ASYNC NEW_CORE C216 name=collection1 org.apache.solr.core.SolrCore@cadcdb url=http://127.0.0.1:50624/collection1 node=127.0.0.1:50624_ C216_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:50624_, base_url=http://127.0.0.1:50624, leader=true}
[junit4:junit4] 2> 1187694 T4482 C216 P50624 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> 1187698 T4477 C216 P50624 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1187700 T4477 C216 P50624 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3e8674 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a4cf80),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1187701 T4477 C216 P50624 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1187701 T4477 C216 P50624 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3e8674 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a4cf80),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3e8674 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a4cf80),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1187702 T4477 C216 P50624 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1187702 T4477 C216 P50624 oass.SolrIndexSearcher.<init> Opening Searcher@3525c3 realtime
[junit4:junit4] 2> 1187703 T4477 C216 P50624 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1187703 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&openSearcher=false&commit=true&wt=javabin&commit_end_point=true&version=2&softCommit=false} {commit=} 0 5
[junit4:junit4] 2> 1187704 T4521 C214 P45691 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1187704 T4521 C214 P45691 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1187707 T4481 C216 P50624 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1187707 T4481 C216 P50624 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=2
[junit4:junit4] 2> 1187708 T4521 C214 P45691 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1187708 T4521 C214 P45691 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1187708 T4521 C214 P45691 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1187710 T4482 C216 P50624 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 1187712 T4521 C214 P45691 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1187713 T4521 C214 P45691 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty3/index.20130521054411502
[junit4:junit4] 2> 1187713 T4521 C214 P45691 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@2a3cd5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1f4094f) fullCopy=false
[junit4:junit4] 2> 1187715 T4477 C216 P50624 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> 1187717 T4521 C214 P45691 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1187718 T4521 C214 P45691 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1187718 T4521 C214 P45691 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1187719 T4521 C214 P45691 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d51aca lockFactory=org.apache.lucene.store.NativeFSLockFactory@c84ba8),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d51aca lockFactory=org.apache.lucene.store.NativeFSLockFactory@c84ba8),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1187720 T4521 C214 P45691 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1187720 T4521 C214 P45691 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1187720 T4521 C214 P45691 oass.SolrIndexSearcher.<init> Opening Searcher@763c62 main
[junit4:junit4] 2> 1187721 T4520 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@763c62 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1187722 T4521 C214 P45691 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty3/index.20130521054411502 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty3/index.20130521054411502;done=true>>]
[junit4:junit4] 2> 1187722 T4521 C214 P45691 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty3/index.20130521054411502
[junit4:junit4] 2> 1187722 T4521 C214 P45691 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty3/index.20130521054411502
[junit4:junit4] 2> 1187722 T4521 C214 P45691 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1187722 T4521 C214 P45691 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1187723 T4521 C214 P45691 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1187723 T4521 C214 P45691 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1187724 T4521 C214 P45691 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1188250 T4444 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1188660 T4467 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1188661 T4467 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:40528__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:40528_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40528"}
[junit4:junit4] 2> 1188665 T4467 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:45691__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:45691_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:45691"}
[junit4:junit4] 2> 1188667 T4535 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> 1188667 T4473 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> 1188668 T4466 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> 1188667 T4486 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> 1188667 T4518 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> 1188667 T4502 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> 1189248 T4498 oasha.CoreAdminHandler.handleWaitForStateAction Waited coreNodeName: 127.0.0.1:40528__collection1, state: recovering, checkLive: true, onlyIfLeader: true for: 2 seconds.
[junit4:junit4] 2> 1189249 T4498 oass.SolrDispatchFilter.handleAdminRequest [admin] webapp=null path=/admin/cores params={coreNodeName=127.0.0.1:40528__collection1&state=recovering&nodeName=127.0.0.1:40528_&action=PREPRECOVERY&checkLive=true&core=collection1&wt=javabin&onlyIfLeader=true&version=2} status=0 QTime=2001
[junit4:junit4] 2> 1189252 T4444 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1190253 T4444 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> C215_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=recovering, core=collection1, collection=collection1, node_name=127.0.0.1:40528_, base_url=http://127.0.0.1:40528}
[junit4:junit4] 2> 1191250 T4538 C215 P40528 oasc.RecoveryStrategy.doRecovery Attempting to PeerSync from http://127.0.0.1:47652/collection1/ core=collection1 - recoveringAfterStartup=true
[junit4:junit4] 2> 1191250 T4538 C215 P40528 oasu.PeerSync.sync PeerSync: core=collection1 url=http://127.0.0.1:40528 START replicas=[http://127.0.0.1:47652/collection1/] nUpdates=100
[junit4:junit4] 2> 1191251 T4538 C215 P40528 oasu.PeerSync.sync WARN no frame of reference to tell of we've missed updates
[junit4:junit4] 2> 1191251 T4538 C215 P40528 oasc.RecoveryStrategy.doRecovery PeerSync Recovery was not successful - trying replication. core=collection1
[junit4:junit4] 2> 1191251 T4538 C215 P40528 oasc.RecoveryStrategy.doRecovery Starting Replication Recovery. core=collection1
[junit4:junit4] 2> 1191251 T4538 C215 P40528 oasc.RecoveryStrategy.doRecovery Begin buffering updates. core=collection1
[junit4:junit4] 2> 1191251 T4538 C215 P40528 oasu.UpdateLog.bufferUpdates Starting to buffer updates. FSUpdateLog{state=ACTIVE, tlog=null}
[junit4:junit4] 2> 1191252 T4538 C215 P40528 oasc.RecoveryStrategy.replicate Attempting to replicate from http://127.0.0.1:47652/collection1/. core=collection1
[junit4:junit4] 2> 1191252 T4538 C215 P40528 oascsi.HttpClientUtil.createClient Creating new http client, config:maxConnections=128&maxConnectionsPerHost=32&followRedirects=false
[junit4:junit4] 2> 1191255 T4444 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> ASYNC NEW_CORE C217 name=collection1 org.apache.solr.core.SolrCore@15a2061 url=http://127.0.0.1:47652/collection1 node=127.0.0.1:47652_ C217_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:47652_, base_url=http://127.0.0.1:47652, leader=true}
[junit4:junit4] 2> 1191257 T4498 C217 P47652 oasc.SolrCore.execute [collection1] webapp= path=/get params={getVersions=100&distrib=false&wt=javabin&qt=/get&version=2} status=0 QTime=2
[junit4:junit4] 2> 1191259 T4495 C217 P47652 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1191260 T4495 C217 P47652 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@113aed5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@19b3118),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1191261 T4495 C217 P47652 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1191261 T4495 C217 P47652 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@113aed5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@19b3118),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@113aed5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@19b3118),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1191262 T4495 C217 P47652 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1191262 T4495 C217 P47652 oass.SolrIndexSearcher.<init> Opening Searcher@664a0f realtime
[junit4:junit4] 2> 1191262 T4495 C217 P47652 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1191263 T4495 C217 P47652 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 4
[junit4:junit4] 2> 1191263 T4538 C215 P40528 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1191264 T4538 C215 P40528 oash.SnapPuller.<init> No value set for 'pollInterval'. Timer Task not started.
[junit4:junit4] 2> 1191265 T4495 C217 P47652 oash.ReplicationHandler.inform Commits will be reserved for 10000
[junit4:junit4] 2> 1191265 T4495 C217 P47652 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=indexversion&qt=/replication&wt=javabin&version=2} status=0 QTime=0
[junit4:junit4] 2> 1191266 T4538 C215 P40528 oash.SnapPuller.fetchLatestIndex Master's generation: 2
[junit4:junit4] 2> 1191266 T4538 C215 P40528 oash.SnapPuller.fetchLatestIndex Slave's generation: 1
[junit4:junit4] 2> 1191266 T4538 C215 P40528 oash.SnapPuller.fetchLatestIndex Starting replication process
[junit4:junit4] 2> 1191268 T4496 C217 P47652 oasc.SolrCore.execute [collection1] webapp= path=/replication params={command=filelist&qt=/replication&wt=javabin&generation=2&version=2} status=0 QTime=0
[junit4:junit4] 2> 1191268 T4538 C215 P40528 oash.SnapPuller.fetchLatestIndex Number of files in latest index in master: 1
[junit4:junit4] 2> 1191269 T4538 C215 P40528 oasc.CachingDirectoryFactory.get return new directory for ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4/index.20130521054415058
[junit4:junit4] 2> 1191269 T4538 C215 P40528 oash.SnapPuller.fetchLatestIndex Starting download to MockDirWrapper(org.apache.lucene.store.RAMDirectory@69d3d lockFactory=org.apache.lucene.store.NativeFSLockFactory@e60187) fullCopy=false
[junit4:junit4] 2> 1191272 T4497 C217 P47652 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> 1191273 T4538 C215 P40528 oash.SnapPuller.fetchLatestIndex Total time taken for download : 0 secs
[junit4:junit4] 2> 1191273 T4538 C215 P40528 oasu.DefaultSolrCoreState.newIndexWriter Creating new IndexWriter...
[junit4:junit4] 2> 1191273 T4538 C215 P40528 oasu.DefaultSolrCoreState.newIndexWriter Waiting until IndexWriter is unused... core=collection1
[junit4:junit4] 2> 1191274 T4538 C215 P40528 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@14d4729 lockFactory=org.apache.lucene.store.NativeFSLockFactory@11fb59a),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@14d4729 lockFactory=org.apache.lucene.store.NativeFSLockFactory@11fb59a),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1191275 T4538 C215 P40528 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1191275 T4538 C215 P40528 oasu.DefaultSolrCoreState.newIndexWriter New IndexWriter is ready to be used.
[junit4:junit4] 2> 1191276 T4538 C215 P40528 oass.SolrIndexSearcher.<init> Opening Searcher@9667ae main
[junit4:junit4] 2> 1191276 T4537 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@9667ae main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1191277 T4538 C215 P40528 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4/index.20130521054415058 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4/index.20130521054415058;done=true>>]
[junit4:junit4] 2> 1191277 T4538 C215 P40528 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4/index.20130521054415058
[junit4:junit4] 2> 1191277 T4538 C215 P40528 oasc.CachingDirectoryFactory.closeCacheValue Removing directory before core close: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4/index.20130521054415058
[junit4:junit4] 2> 1191277 T4538 C215 P40528 oasc.RecoveryStrategy.replay No replay needed. core=collection1
[junit4:junit4] 2> 1191278 T4538 C215 P40528 oasc.RecoveryStrategy.doRecovery Replication Recovery was successful - registering as Active. core=collection1
[junit4:junit4] 2> 1191278 T4538 C215 P40528 oasc.ZkController.publish publishing core=collection1 state=active
[junit4:junit4] 2> 1191278 T4538 C215 P40528 oasc.ZkController.publish numShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1191280 T4538 C215 P40528 oasc.RecoveryStrategy.doRecovery Finished recovery process. core=collection1
[junit4:junit4] 2> 1191673 T4467 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1191674 T4467 oasc.Overseer$ClusterStateUpdater.updateState Update state numShards=2 message={
[junit4:junit4] 2> "operation":"state",
[junit4:junit4] 2> "core_node_name":"127.0.0.1:40528__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:40528_",
[junit4:junit4] 2> "base_url":"http://127.0.0.1:40528"}
[junit4:junit4] 2> 1191678 T4502 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> 1191678 T4535 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> 1191678 T4486 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> 1191678 T4466 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> 1191678 T4518 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> 1191678 T4473 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> 1192258 T4444 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1192259 T4444 oasc.AbstractDistribZkTestBase.waitForRecoveriesToFinish Recoveries finished - collection: collection1
[junit4:junit4] 2> ASYNC NEW_CORE C218 name=collection1 org.apache.solr.core.SolrCore@1b4b575 url=http://127.0.0.1:54981/collection1 node=127.0.0.1:54981_ C218_STATE=coll:control_collection core:collection1 props:{shard=shard1, state=active, core=collection1, collection=control_collection, node_name=127.0.0.1:54981_, base_url=http://127.0.0.1:54981, leader=true}
[junit4:junit4] 2> 1192265 T4462 C218 P54981 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1192266 T4462 C218 P54981 oasc.SolrDeletionPolicy.onInit SolrDeletionPolicy.onInit: commits: num=1
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4643fd lockFactory=org.apache.lucene.store.NativeFSLockFactory@165d06b),segFN=segments_1,generation=1}
[junit4:junit4] 2> 1192267 T4462 C218 P54981 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 1
[junit4:junit4] 2> 1192268 T4462 C218 P54981 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4643fd lockFactory=org.apache.lucene.store.NativeFSLockFactory@165d06b),segFN=segments_1,generation=1}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@4643fd lockFactory=org.apache.lucene.store.NativeFSLockFactory@165d06b),segFN=segments_2,generation=2}
[junit4:junit4] 2> 1192269 T4462 C218 P54981 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 2
[junit4:junit4] 2> 1192269 T4462 C218 P54981 oass.SolrIndexSearcher.<init> Opening Searcher@1bafdfd main
[junit4:junit4] 2> 1192270 T4462 C218 P54981 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1192270 T4470 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1bafdfd main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1192271 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 1192275 T4498 C217 P47652 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1192276 T4498 C217 P47652 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@113aed5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@19b3118),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@113aed5 lockFactory=org.apache.lucene.store.NativeFSLockFactory@19b3118),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1192276 T4498 C217 P47652 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1192277 T4498 C217 P47652 oass.SolrIndexSearcher.<init> Opening Searcher@1f56f83 main
[junit4:junit4] 2> 1192277 T4498 C217 P47652 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1192278 T4504 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1f56f83 main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1192278 T4498 C217 P47652 oasu.SolrCmdDistributor.distribCommit Distrib commit to:[StdNode: http://127.0.0.1:50624/collection1/, StdNode: http://127.0.0.1:45691/collection1/, StdNode: http://127.0.0.1:40528/collection1/] params:commit_end_point=true&commit=true&softCommit=false&waitSearcher=true&expungeDeletes=false
[junit4:junit4] 2> 1192285 T4481 C216 P50624 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> C215_STATE=coll:collection1 core:collection1 props:{shard=shard2, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:40528_, base_url=http://127.0.0.1:40528}
[junit4:junit4] 2> 1192288 T4529 C215 P40528 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1192289 T4481 C216 P50624 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3e8674 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a4cf80),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@3e8674 lockFactory=org.apache.lucene.store.NativeFSLockFactory@1a4cf80),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1192289 T4529 C215 P40528 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@14d4729 lockFactory=org.apache.lucene.store.NativeFSLockFactory@11fb59a),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@14d4729 lockFactory=org.apache.lucene.store.NativeFSLockFactory@11fb59a),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1192290 T4529 C215 P40528 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> C214_STATE=coll:collection1 core:collection1 props:{shard=shard1, state=active, core=collection1, collection=collection1, node_name=127.0.0.1:45691_, base_url=http://127.0.0.1:45691}
[junit4:junit4] 2> 1192289 T4512 C214 P45691 oasu.DirectUpdateHandler2.commit start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
[junit4:junit4] 2> 1192289 T4481 C216 P50624 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1192291 T4512 C214 P45691 oasc.SolrDeletionPolicy.onCommit SolrDeletionPolicy.onCommit: commits: num=2
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d51aca lockFactory=org.apache.lucene.store.NativeFSLockFactory@c84ba8),segFN=segments_2,generation=2}
[junit4:junit4] 2> commit{dir=MockDirWrapper(org.apache.lucene.store.RAMDirectory@d51aca lockFactory=org.apache.lucene.store.NativeFSLockFactory@c84ba8),segFN=segments_3,generation=3}
[junit4:junit4] 2> 1192291 T4529 C215 P40528 oass.SolrIndexSearcher.<init> Opening Searcher@1d92e6a main
[junit4:junit4] 2> 1192292 T4512 C214 P45691 oasc.SolrDeletionPolicy.updateCommits newest commit generation = 3
[junit4:junit4] 2> 1192291 T4481 C216 P50624 oass.SolrIndexSearcher.<init> Opening Searcher@18e2b4d main
[junit4:junit4] 2> 1192293 T4512 C214 P45691 oass.SolrIndexSearcher.<init> Opening Searcher@e3844e main
[junit4:junit4] 2> 1192293 T4537 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@1d92e6a main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1192292 T4529 C215 P40528 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1192294 T4520 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@e3844e main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1192294 T4488 oasc.SolrCore.registerSearcher [collection1] Registered new searcher Searcher@18e2b4d main{StandardDirectoryReader(segments_2:1:nrt)}
[junit4:junit4] 2> 1192294 T4512 C214 P45691 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1192293 T4481 C216 P50624 oasu.DirectUpdateHandler2.commit end_commit_flush
[junit4:junit4] 2> 1192295 T4512 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 1192294 T4529 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&expungeDeletes=false&commit_end_point=true&version=2&softCommit=false} {commit=} 0 6
[junit4:junit4] 2> 1192295 T4481 C216 P50624 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 10
[junit4:junit4] 2> 1192296 T4498 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={waitSearcher=true&commit=true&wt=javabin&version=2&softCommit=false} {commit=} 0 21
[junit4:junit4] 2> 1192297 T4444 oascc.ZkStateReader.updateClusterState Updating cloud state from ZooKeeper...
[junit4:junit4] 2> 1192299 T4477 C216 P50624 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> 1192300 T4513 C214 P45691 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> 1192302 T4496 C217 P47652 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> 1192303 T4526 C215 P40528 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> 1194306 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435613641409822720)} 0 1
[junit4:junit4] 2> 1194310 T4513 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435613641411919872&update.from=http://127.0.0.1:50624/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435613641411919872)} 0 0
[junit4:junit4] 2> 1194312 T4529 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=FROMLEADER&_version_=-1435613641415065600&update.from=http://127.0.0.1:47652/collection1/&wt=javabin&version=2} {deleteByQuery=*:* (-1435613641415065600)} 0 0
[junit4:junit4] 2> 1194313 T4495 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={update.distrib=TOLEADER&wt=javabin&version=2} {deleteByQuery=*:* (-1435613641415065600)} 0 3
[junit4:junit4] 2> 1194313 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {deleteByQuery=*:* (-1435613641411919872)} 0 6
[junit4:junit4] 2> 1194316 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0 (1435613641420308480)]} 0 1
[junit4:junit4] 2> 1194321 T4514 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[0 (1435613641424502784)]} 0 0
[junit4:junit4] 2> 1194322 T4479 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[0 (1435613641424502784)]} 0 3
[junit4:junit4] 2> 1194322 T4496 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[0]} 0 4
[junit4:junit4] 2> 1194324 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1435613641429745664)]} 0 0
[junit4:junit4] 2> 1194328 T4511 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[1 (1435613641431842816)]} 0 0
[junit4:junit4] 2> 1194328 T4482 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[1 (1435613641431842816)]} 0 2
[junit4:junit4] 2> 1194330 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1435613641436037120)]} 0 0
[junit4:junit4] 2> 1194334 T4526 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[2 (1435613641438134272)]} 0 0
[junit4:junit4] 2> 1194335 T4497 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[2 (1435613641438134272)]} 0 3
[junit4:junit4] 2> 1194336 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1435613641442328576)]} 0 0
[junit4:junit4] 2> 1194340 T4530 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[3 (1435613641444425728)]} 0 0
[junit4:junit4] 2> 1194341 T4498 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[3 (1435613641444425728)]} 0 3
[junit4:junit4] 2> 1194343 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1435613641449668608)]} 0 1
[junit4:junit4] 2> 1194346 T4512 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[4 (1435613641451765760)]} 0 0
[junit4:junit4] 2> 1194347 T4481 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[4 (1435613641451765760)]} 0 2
[junit4:junit4] 2> 1194349 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5 (1435613641455960064)]} 0 0
[junit4:junit4] 2> 1194354 T4531 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[5 (1435613641459105792)]} 0 0
[junit4:junit4] 2> 1194354 T4495 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[5 (1435613641459105792)]} 0 2
[junit4:junit4] 2> 1194355 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[5]} 0 5
[junit4:junit4] 2> 1194357 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1435613641464348672)]} 0 0
[junit4:junit4] 2> 1194360 T4529 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[6 (1435613641466445824)]} 0 0
[junit4:junit4] 2> 1194361 T4496 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[6 (1435613641466445824)]} 0 3
[junit4:junit4] 2> 1194363 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1435613641469591552)]} 0 1
[junit4:junit4] 2> 1194366 T4526 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[7 (1435613641471688704)]} 0 0
[junit4:junit4] 2> 1194367 T4497 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[7 (1435613641471688704)]} 0 3
[junit4:junit4] 2> 1194368 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8 (1435613641475883008)]} 0 0
[junit4:junit4] 2> 1194373 T4513 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[8 (1435613641480077312)]} 0 0
[junit4:junit4] 2> 1194374 T4479 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[8 (1435613641480077312)]} 0 2
[junit4:junit4] 2> 1194374 T4498 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[8]} 0 4
[junit4:junit4] 2> 1194376 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9 (1435613641484271616)]} 0 0
[junit4:junit4] 2> 1194381 T4530 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[9 (1435613641487417344)]} 0 0
[junit4:junit4] 2> 1194382 T4495 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[9 (1435613641487417344)]} 0 3
[junit4:junit4] 2> 1194382 T4482 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[9]} 0 4
[junit4:junit4] 2> 1194384 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10 (1435613641492660224)]} 0 0
[junit4:junit4] 2> 1194389 T4514 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[10 (1435613641495805952)]} 0 0
[junit4:junit4] 2> 1194389 T4481 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[10 (1435613641495805952)]} 0 2
[junit4:junit4] 2> 1194390 T4496 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[10]} 0 4
[junit4:junit4] 2> 1194392 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11 (1435613641501048832)]} 0 0
[junit4:junit4] 2> 1194397 T4511 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[11 (1435613641504194560)]} 0 1
[junit4:junit4] 2> 1194397 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[11 (1435613641504194560)]} 0 2
[junit4:junit4] 2> 1194397 T4497 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[11]} 0 3
[junit4:junit4] 2> 1194399 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12 (1435613641508388864)]} 0 0
[junit4:junit4] 2> 1194404 T4512 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[12 (1435613641512583168)]} 0 0
[junit4:junit4] 2> 1194405 T4479 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[12 (1435613641512583168)]} 0 2
[junit4:junit4] 2> 1194405 T4498 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[12]} 0 4
[junit4:junit4] 2> 1194407 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13 (1435613641516777472)]} 0 0
[junit4:junit4] 2> 1194412 T4513 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[13 (1435613641520971776)]} 0 0
[junit4:junit4] 2> 1194413 T4482 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[13 (1435613641520971776)]} 0 2
[junit4:junit4] 2> 1194413 T4495 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[13]} 0 4
[junit4:junit4] 2> 1194430 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14 (1435613641525166080)]} 0 15
[junit4:junit4] 2> 1194436 T4514 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[14 (1435613641545089024)]} 0 0
[junit4:junit4] 2> 1194437 T4481 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[14 (1435613641545089024)]} 0 3
[junit4:junit4] 2> 1194437 T4496 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[14]} 0 4
[junit4:junit4] 2> 1194439 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1435613641550331904)]} 0 0
[junit4:junit4] 2> 1194443 T4511 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[15 (1435613641552429056)]} 0 1
[junit4:junit4] 2> 1194443 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[15 (1435613641552429056)]} 0 2
[junit4:junit4] 2> 1194445 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16 (1435613641556623360)]} 0 0
[junit4:junit4] 2> 1194450 T4512 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[16 (1435613641559769088)]} 0 0
[junit4:junit4] 2> 1194451 T4479 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[16 (1435613641559769088)]} 0 3
[junit4:junit4] 2> 1194451 T4497 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[16]} 0 4
[junit4:junit4] 2> 1194453 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1435613641565011968)]} 0 0
[junit4:junit4] 2> 1194457 T4531 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[17 (1435613641567109120)]} 0 1
[junit4:junit4] 2> 1194457 T4498 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[17 (1435613641567109120)]} 0 2
[junit4:junit4] 2> 1194459 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18 (1435613641571303424)]} 0 0
[junit4:junit4] 2> 1194464 T4529 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[18 (1435613641574449152)]} 0 0
[junit4:junit4] 2> 1194465 T4495 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[18 (1435613641574449152)]} 0 3
[junit4:junit4] 2> 1194465 T4482 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[18]} 0 4
[junit4:junit4] 2> 1194467 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19 (1435613641579692032)]} 0 0
[junit4:junit4] 2> 1194472 T4526 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[19 (1435613641582837760)]} 0 0
[junit4:junit4] 2> 1194472 T4496 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[19 (1435613641582837760)]} 0 2
[junit4:junit4] 2> 1194473 T4481 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[19]} 0 4
[junit4:junit4] 2> 1194475 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1435613641588080640)]} 0 0
[junit4:junit4] 2> 1194479 T4513 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[20 (1435613641590177792)]} 0 0
[junit4:junit4] 2> 1194479 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[20 (1435613641590177792)]} 0 2
[junit4:junit4] 2> 1194481 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1435613641594372096)]} 0 0
[junit4:junit4] 2> 1194485 T4530 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[21 (1435613641596469248)]} 0 0
[junit4:junit4] 2> 1194486 T4497 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[21 (1435613641596469248)]} 0 3
[junit4:junit4] 2> 1194487 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1435613641600663552)]} 0 0
[junit4:junit4] 2> 1194491 T4514 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[22 (1435613641602760704)]} 0 0
[junit4:junit4] 2> 1194491 T4479 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[22 (1435613641602760704)]} 0 2
[junit4:junit4] 2> 1194493 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23 (1435613641606955008)]} 0 0
[junit4:junit4] 2> 1194499 T4531 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[23 (1435613641611149312)]} 0 1
[junit4:junit4] 2> 1194499 T4498 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[23 (1435613641611149312)]} 0 2
[junit4:junit4] 2> 1194500 T4482 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[23]} 0 5
[junit4:junit4] 2> 1194502 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24 (1435613641615343616)]} 0 1
[junit4:junit4] 2> 1194507 T4511 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[24 (1435613641619537920)]} 0 1
[junit4:junit4] 2> 1194507 T4481 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[24 (1435613641619537920)]} 0 2
[junit4:junit4] 2> 1194508 T4495 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[24]} 0 5
[junit4:junit4] 2> 1194509 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1435613641623732224)]} 0 0
[junit4:junit4] 2> 1194513 T4529 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[25 (1435613641625829376)]} 0 0
[junit4:junit4] 2> 1194513 T4496 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[25 (1435613641625829376)]} 0 2
[junit4:junit4] 2> 1194515 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26 (1435613641630023680)]} 0 0
[junit4:junit4] 2> 1194520 T4526 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[26 (1435613641634217984)]} 0 0
[junit4:junit4] 2> 1194521 T4497 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[26 (1435613641634217984)]} 0 3
[junit4:junit4] 2> 1194521 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[26]} 0 4
[junit4:junit4] 2> 1194523 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1435613641638412288)]} 0 0
[junit4:junit4] 2> 1194527 T4512 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[27 (1435613641640509440)]} 0 1
[junit4:junit4] 2> 1194527 T4479 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[27 (1435613641640509440)]} 0 2
[junit4:junit4] 2> 1194529 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28 (1435613641644703744)]} 0 0
[junit4:junit4] 2> 1194534 T4513 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[28 (1435613641647849472)]} 0 0
[junit4:junit4] 2> 1194535 T4482 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[28 (1435613641647849472)]} 0 3
[junit4:junit4] 2> 1194535 T4498 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[28]} 0 4
[junit4:junit4] 2> 1194537 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29 (1435613641653092352)]} 0 0
[junit4:junit4] 2> 1194543 T4530 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[29 (1435613641657286656)]} 0 1
[junit4:junit4] 2> 1194543 T4495 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[29 (1435613641657286656)]} 0 2
[junit4:junit4] 2> 1194544 T4481 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[29]} 0 5
[junit4:junit4] 2> 1194545 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30 (1435613641661480960)]} 0 0
[junit4:junit4] 2> 1194550 T4531 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[30 (1435613641665675264)]} 0 0
[junit4:junit4] 2> 1194551 T4496 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[30 (1435613641665675264)]} 0 2
[junit4:junit4] 2> 1194551 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[30]} 0 4
[junit4:junit4] 2> 1194553 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1435613641669869568)]} 0 0
[junit4:junit4] 2> 1194557 T4529 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[31 (1435613641671966720)]} 0 1
[junit4:junit4] 2> 1194557 T4497 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[31 (1435613641671966720)]} 0 2
[junit4:junit4] 2> 1194559 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32 (1435613641676161024)]} 0 0
[junit4:junit4] 2> 1194564 T4514 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[32 (1435613641679306752)]} 0 0
[junit4:junit4] 2> 1194564 T4479 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[32 (1435613641679306752)]} 0 2
[junit4:junit4] 2> 1194565 T4498 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[32]} 0 4
[junit4:junit4] 2> 1194567 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1435613641684549632)]} 0 0
[junit4:junit4] 2> 1194570 T4526 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[33 (1435613641686646784)]} 0 0
[junit4:junit4] 2> 1194571 T4495 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[33 (1435613641686646784)]} 0 2
[junit4:junit4] 2> 1194573 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1435613641689792512)]} 0 1
[junit4:junit4] 2> 1194576 T4511 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[34 (1435613641691889664)]} 0 0
[junit4:junit4] 2> 1194576 T4482 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[34 (1435613641691889664)]} 0 2
[junit4:junit4] 2> 1194578 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1435613641696083968)]} 0 0
[junit4:junit4] 2> 1194581 T4512 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[35 (1435613641698181120)]} 0 0
[junit4:junit4] 2> 1194582 T4481 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[35 (1435613641698181120)]} 0 2
[junit4:junit4] 2> 1194584 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1435613641701326848)]} 0 1
[junit4:junit4] 2> 1194587 T4513 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[36 (1435613641703424000)]} 0 0
[junit4:junit4] 2> 1194587 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[36 (1435613641703424000)]} 0 2
[junit4:junit4] 2> 1194589 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1435613641707618304)]} 0 0
[junit4:junit4] 2> 1194593 T4530 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[37 (1435613641709715456)]} 0 1
[junit4:junit4] 2> 1194593 T4496 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[37 (1435613641709715456)]} 0 2
[junit4:junit4] 2> 1194595 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38 (1435613641713909760)]} 0 0
[junit4:junit4] 2> 1194600 T4514 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[38 (1435613641717055488)]} 0 1
[junit4:junit4] 2> 1194600 T4479 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[38 (1435613641717055488)]} 0 2
[junit4:junit4] 2> 1194600 T4497 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[38]} 0 3
[junit4:junit4] 2> 1194602 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39 (1435613641721249792)]} 0 0
[junit4:junit4] 2> 1194607 T4531 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[39 (1435613641724395520)]} 0 0
[junit4:junit4] 2> 1194607 T4498 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[39 (1435613641724395520)]} 0 2
[junit4:junit4] 2> 1194608 T4482 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[39]} 0 4
[junit4:junit4] 2> 1194609 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1435613641728589824)]} 0 0
[junit4:junit4] 2> 1194613 T4511 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[40 (1435613641730686976)]} 0 1
[junit4:junit4] 2> 1194613 T4481 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[40 (1435613641730686976)]} 0 2
[junit4:junit4] 2> 1194615 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1435613641734881280)]} 0 0
[junit4:junit4] 2> 1194618 T4512 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[41 (1435613641736978432)]} 0 0
[junit4:junit4] 2> 1194619 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[41 (1435613641736978432)]} 0 2
[junit4:junit4] 2> 1194621 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1435613641740124160)]} 0 1
[junit4:junit4] 2> 1194624 T4513 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[42 (1435613641742221312)]} 0 0
[junit4:junit4] 2> 1194624 T4479 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[42 (1435613641742221312)]} 0 2
[junit4:junit4] 2> 1194626 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43 (1435613641746415616)]} 0 0
[junit4:junit4] 2> 1194631 T4514 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[43 (1435613641749561344)]} 0 0
[junit4:junit4] 2> 1194632 T4482 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[43 (1435613641749561344)]} 0 2
[junit4:junit4] 2> 1194632 T4495 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[43]} 0 4
[junit4:junit4] 2> 1194634 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1435613641754804224)]} 0 1
[junit4:junit4] 2> 1194637 T4511 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[44 (1435613641755852800)]} 0 0
[junit4:junit4] 2> 1194637 T4481 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[44 (1435613641755852800)]} 0 2
[junit4:junit4] 2> 1194639 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1435613641760047104)]} 0 0
[junit4:junit4] 2> 1194643 T4529 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[45 (1435613641763192832)]} 0 0
[junit4:junit4] 2> 1194644 T4496 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[45 (1435613641763192832)]} 0 3
[junit4:junit4] 2> 1194646 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46 (1435613641766338560)]} 0 1
[junit4:junit4] 2> 1194651 T4512 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[46 (1435613641770532864)]} 0 1
[junit4:junit4] 2> 1194651 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[46 (1435613641770532864)]} 0 2
[junit4:junit4] 2> 1194651 T4497 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[46]} 0 4
[junit4:junit4] 2> 1194653 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1435613641774727168)]} 0 0
[junit4:junit4] 2> 1194657 T4513 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[47 (1435613641776824320)]} 0 1
[junit4:junit4] 2> 1194657 T4479 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[47 (1435613641776824320)]} 0 2
[junit4:junit4] 2> 1194659 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1435613641781018624)]} 0 1
[junit4:junit4] 2> 1194662 T4514 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[48 (1435613641782067200)]} 0 0
[junit4:junit4] 2> 1194662 T4482 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[48 (1435613641782067200)]} 0 2
[junit4:junit4] 2> 1194664 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49 (1435613641786261504)]} 0 0
[junit4:junit4] 2> 1194669 T4511 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[49 (1435613641789407232)]} 0 0
[junit4:junit4] 2> 1194669 T4481 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[49 (1435613641789407232)]} 0 2
[junit4:junit4] 2> 1194670 T4498 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[49]} 0 4
[junit4:junit4] 2> 1194672 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50 (1435613641793601536)]} 0 1
[junit4:junit4] 2> 1194676 T4512 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[50 (1435613641797795840)]} 0 0
[junit4:junit4] 2> 1194677 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[50 (1435613641797795840)]} 0 2
[junit4:junit4] 2> 1194677 T4495 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[50]} 0 4
[junit4:junit4] 2> 1194679 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1435613641801990144)]} 0 0
[junit4:junit4] 2> 1194682 T4513 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[51 (1435613641804087296)]} 0 0
[junit4:junit4] 2> 1194683 T4479 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[51 (1435613641804087296)]} 0 2
[junit4:junit4] 2> 1194685 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1435613641808281600)]} 0 1
[junit4:junit4] 2> 1194688 T4514 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[52 (1435613641809330176)]} 0 0
[junit4:junit4] 2> 1194688 T4482 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[52 (1435613641809330176)]} 0 2
[junit4:junit4] 2> 1194690 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53 (1435613641813524480)]} 0 0
[junit4:junit4] 2> 1194695 T4526 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[53 (1435613641816670208)]} 0 0
[junit4:junit4] 2> 1194695 T4496 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[53 (1435613641816670208)]} 0 2
[junit4:junit4] 2> 1194696 T4481 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[53]} 0 4
[junit4:junit4] 2> 1194697 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1435613641820864512)]} 0 0
[junit4:junit4] 2> 1194701 T4511 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[54 (1435613641822961664)]} 0 0
[junit4:junit4] 2> 1194701 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[54 (1435613641822961664)]} 0 2
[junit4:junit4] 2> 1194703 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1435613641827155968)]} 0 0
[junit4:junit4] 2> 1194707 T4513 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[55 (1435613641829253120)]} 0 0
[junit4:junit4] 2> 1194707 T4479 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[55 (1435613641829253120)]} 0 2
[junit4:junit4] 2> 1194709 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56 (1435613641833447424)]} 0 0
[junit4:junit4] 2> 1194714 T4531 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[56 (1435613641836593152)]} 0 0
[junit4:junit4] 2> 1194714 T4498 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[56 (1435613641836593152)]} 0 2
[junit4:junit4] 2> 1194714 T4481 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[56]} 0 3
[junit4:junit4] 2> 1194716 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57 (1435613641840787456)]} 0 0
[junit4:junit4] 2> 1194721 T4526 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[57 (1435613641844981760)]} 0 0
[junit4:junit4] 2> 1194721 T4496 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[57 (1435613641844981760)]} 0 2
[junit4:junit4] 2> 1194722 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[57]} 0 4
[junit4:junit4] 2> 1194724 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1435613641849176064)]} 0 0
[junit4:junit4] 2> 1194727 T4530 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[58 (1435613641850224640)]} 0 0
[junit4:junit4] 2> 1194727 T4497 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[58 (1435613641850224640)]} 0 2
[junit4:junit4] 2> 1194729 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1435613641854418944)]} 0 0
[junit4:junit4] 2> 1194733 T4514 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[59 (1435613641856516096)]} 0 1
[junit4:junit4] 2> 1194733 T4479 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[59 (1435613641856516096)]} 0 2
[junit4:junit4] 2> 1194735 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60 (1435613641860710400)]} 0 0
[junit4:junit4] 2> 1194739 T4529 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[60 (1435613641863856128)]} 0 0
[junit4:junit4] 2> 1194740 T4495 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[60 (1435613641863856128)]} 0 2
[junit4:junit4] 2> 1194740 T4482 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[60]} 0 4
[junit4:junit4] 2> 1194742 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1435613641868050432)]} 0 0
[junit4:junit4] 2> 1194745 T4512 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[61 (1435613641870147584)]} 0 0
[junit4:junit4] 2> 1194746 T4481 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[61 (1435613641870147584)]} 0 2
[junit4:junit4] 2> 1194748 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1435613641873293312)]} 0 1
[junit4:junit4] 2> 1194751 T4531 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[62 (1435613641875390464)]} 0 0
[junit4:junit4] 2> 1194751 T4498 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[62 (1435613641875390464)]} 0 2
[junit4:junit4] 2> 1194753 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1435613641879584768)]} 0 0
[junit4:junit4] 2> 1194757 T4511 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[63 (1435613641881681920)]} 0 1
[junit4:junit4] 2> 1194757 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[63 (1435613641881681920)]} 0 2
[junit4:junit4] 2> 1194759 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1435613641885876224)]} 0 0
[junit4:junit4] 2> 1194762 T4513 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[64 (1435613641887973376)]} 0 0
[junit4:junit4] 2> 1194763 T4479 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[64 (1435613641887973376)]} 0 2
[junit4:junit4] 2> 1194765 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1435613641891119104)]} 0 1
[junit4:junit4] 2> 1194768 T4514 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[65 (1435613641893216256)]} 0 0
[junit4:junit4] 2> 1194769 T4482 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[65 (1435613641893216256)]} 0 3
[junit4:junit4] 2> 1194771 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1435613641897410560)]} 0 1
[junit4:junit4] 2> 1194774 T4512 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[66 (1435613641899507712)]} 0 0
[junit4:junit4] 2> 1194774 T4481 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[66 (1435613641899507712)]} 0 2
[junit4:junit4] 2> 1194776 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67 (1435613641903702016)]} 0 0
[junit4:junit4] 2> 1194781 T4526 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[67 (1435613641906847744)]} 0 0
[junit4:junit4] 2> 1194782 T4496 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=TOLEADER&wt=javabin&version=2} {add=[67 (1435613641906847744)]} 0 3
[junit4:junit4] 2> 1194782 T4477 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[67]} 0 4
[junit4:junit4] 2> 1194784 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1435613641912090624)]} 0 0
[junit4:junit4] 2> 1194787 T4530 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[68 (1435613641914187776)]} 0 0
[junit4:junit4] 2> 1194788 T4497 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[68 (1435613641914187776)]} 0 2
[junit4:junit4] 2> 1194790 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69 (1435613641917333504)]} 0 1
[junit4:junit4] 2> 1194793 T4529 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[69 (1435613641919430656)]} 0 0
[junit4:junit4] 2> 1194793 T4495 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[69 (1435613641919430656)]} 0 2
[junit4:junit4] 2> 1194795 T4461 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[70 (1435613641923624960)]} 0 0
[junit4:junit4] 2> 1194798 T4511 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[70 (1435613641925722112)]} 0 0
[junit4:junit4] 2> 1194799 T4479 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[70 (1435613641925722112)]} 0 2
[junit4:junit4] 2> 1194801 T4462 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[71 (1435613641928867840)]} 0 1
[junit4:junit4] 2> 1194804 T4531 C215 P40528 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[71 (1435613641930964992)]} 0 0
[junit4:junit4] 2> 1194804 T4498 C217 P47652 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[71 (1435613641930964992)]} 0 2
[junit4:junit4] 2> 1194806 T4460 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[72 (1435613641935159296)]} 0 0
[junit4:junit4] 2> 1194809 T4513 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[72 (1435613641937256448)]} 0 0
[junit4:junit4] 2> 1194810 T4482 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[72 (1435613641937256448)]} 0 2
[junit4:junit4] 2> 1194812 T4459 C218 P54981 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={wt=javabin&version=2} {add=[73 (1435613641940402176)]} 0 1
[junit4:junit4] 2> 1194817 T4514 C214 P45691 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:50624/collection1/&update.distrib=FROMLEADER&wt=javabin&version=2} {add=[73 (1435613641944596480)]} 0 0
[junit4:junit4] 2> 1194817 T4481 C216 P50624 oasup.LogUpdateProcessor.finish [collection1] webapp= path=/update params={distrib.from=http://127.0.0.1:47652/collection1/&up
[...truncated too long message...]
umShards not found on descriptor - reading it from system property
[junit4:junit4] 2> 1337359 T4444 oasc.SolrCore.close [collection1] CLOSING SolrCore org.apache.solr.core.SolrCore@1e5c724
[junit4:junit4] 2> 1337360 T4444 oasu.DirectUpdateHandler2.close closing DirectUpdateHandler2{commits=4,autocommits=0,soft autocommits=0,optimizes=0,rollbacks=0,expungeDeletes=0,docsPending=0,adds=0,deletesById=0,deletesByQuery=0,errors=0,cumulative_adds=662,cumulative_deletesById=0,cumulative_deletesByQuery=1,cumulative_errors=0}
[junit4:junit4] 2> 1337361 T4444 oasu.SolrCoreState.decrefSolrCoreState Closing SolrCoreState
[junit4:junit4] 2> 1337361 T4444 oasu.DefaultSolrCoreState.closeIndexWriter SolrCoreState ref count has reached 0 - closing IndexWriter
[junit4:junit4] 2> 1337362 T4444 oasu.DefaultSolrCoreState.closeIndexWriter closing IndexWriter with IndexWriterCloser
[junit4:junit4] 2> 1337363 T4444 oasc.SolrCore.closeSearcher [collection1] Closing main searcher on request.
[junit4:junit4] 2> 1337364 T4444 oasc.CachingDirectoryFactory.close Closing MockDirectoryFactory - 2 directories currently being tracked
[junit4:junit4] 2> 1337364 T4444 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4 [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4;done=false>>]
[junit4:junit4] 2> 1337365 T4444 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4
[junit4:junit4] 2> 1337365 T4444 oasc.CachingDirectoryFactory.closeCacheValue looking to close ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4/index [CachedDir<<refCount=0;path=./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4/index;done=false>>]
[junit4:junit4] 2> 1337366 T4444 oasc.CachingDirectoryFactory.close Closing directory: ./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198/jetty4/index
[junit4:junit4] 2> 1337367 T4599 oasc.Overseer$ClusterStateUpdater.amILeader According to ZK I (id=89725850891190284-127.0.0.1:40528_-n_0000000004) am no longer a leader.
[junit4:junit4] 2> 1337368 T4535 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> 1337368 T4535 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1337368 T4535 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1337388 T4444 oejsh.ContextHandler.doStop stopped o.e.j.s.ServletContextHandler{/,null}
[junit4:junit4] 2> 1337451 T4444 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1337453 T4444 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:57974 57974
[junit4:junit4] 2> 1337474 T4444 oasc.ChaosMonkey.monkeyLog monkey: stop shard! 54981
[junit4:junit4] 2> !!!! WARNING: best effort to remove /mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build/solr-core/test/J0/./org.apache.solr.cloud.ChaosMonkeyShardSplitTest-1369107832198 FAILED !!!!!
[junit4:junit4] 2> 1337475 T4444 oas.SolrTestCaseJ4.tearDown ###Ending testDistribSearch
[junit4:junit4] 2> 1337475 T4444 oasc.ZkTestServer.send4LetterWord connecting to 127.0.0.1:57974 57974
[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=374D61786AE1F316 -Dtests.multiplier=3 -Dtests.slow=true -Dtests.locale=it_IT -Dtests.timezone=Europe/Madrid -Dtests.file.encoding=US-ASCII
[junit4:junit4] ERROR 169s J0 | ChaosMonkeyShardSplitTest.testDistribSearch <<<
[junit4:junit4] > Throwable #1: org.apache.solr.client.solrj.impl.HttpSolrServer$RemoteSolrException: Server at http://127.0.0.1:50624 returned non ok status:500, message:Server Error
[junit4:junit4] > at __randomizedtesting.SeedInfo.seed([374D61786AE1F316:B6ABEF601DBE932A]: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:208)
[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> 1337518 T4444 oas.SolrTestCaseJ4.deleteCore ###deleteCore
[junit4:junit4] 2> 169121 T4443 ccr.ThreadLeakControl.checkThreadLeaks WARNING Will linger awaiting termination of 2 leaked thread(s).
[junit4:junit4] 2> 1337583 T4518 oascc.ZkStateReader$2.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> 1337583 T4518 oascc.ZkStateReader$3.process WARN ZooKeeper watch triggered, but Solr cannot talk to ZK
[junit4:junit4] 2> NOTE: test params are: codec=Lucene42: {id=PostingsFormat(name=MockSep), _version_=Lucene41(blocksize=128)}, docValues:{}, sim=DefaultSimilarity, locale=it_IT, timezone=Europe/Madrid
[junit4:junit4] 2> NOTE: Linux 3.2.0-41-generic i386/Oracle Corporation 1.7.0_21 (32-bit)/cpus=8,threads=1,free=123666728,total=221773824
[junit4:junit4] 2> NOTE: All tests run in this JVM: [SynonymTokenizerTest, TestCloudManagedSchemaAddField, SimpleFacetsTest, SearchHandlerTest, DocumentBuilderTest, ShowFileRequestHandlerTest, WordBreakSolrSpellCheckerTest, TestWriterPerf, AutoCommitTest, TestStressRecovery, PreAnalyzedFieldTest, TestFieldCollectionResource, ZkControllerTest, SpellingQueryConverterTest, OverseerTest, TestLRUCache, ChaosMonkeyNothingIsSafeTest, TermVectorComponentTest, TestPHPSerializedResponseWriter, TestDocSet, TestSolrDeletionPolicy1, DistributedTermsComponentTest, DirectSolrConnectionTest, TestQuerySenderListener, TestPropInjectDefaults, TestSolrDeletionPolicy2, QueryElevationComponentTest, PrimUtilsTest, MoreLikeThisHandlerTest, ScriptEngineTest, TestPerFieldSimilarity, TestFieldResource, AliasIntegrationTest, QueryResultKeyTest, TestSurroundQueryParser, TestFastWriter, TestTrie, ShardSplitTest, SolrCoreTest, LeaderElectionTest, TestIBSimilarityFactory, SpatialFilterTest, UpdateRequestProcessorFactoryTest, DistributedSpellCheckComponentTest, ClusterStateUpdateTest, SliceStateTest, CoreAdminHandlerTest, MBeansHandlerTest, MinimalSchemaTest, CSVRequestHandlerTest, ResponseLogComponentTest, ReturnFieldsTest, SoftAutoCommitTest, RegexBoostProcessorTest, DistributedQueryElevationComponentTest, TestExtendedDismaxParser, QueryParsingTest, TestFunctionQuery, TestRemoteStreaming, LukeRequestHandlerTest, CacheHeaderTest, CircularListTest, RecoveryZkTest, TestGroupingSearch, QueryEqualityTest, PluginInfoTest, DirectUpdateHandlerOptimizeTest, SolrInfoMBeanTest, AnalysisAfterCoreReloadTest, BasicFunctionalityTest, DocValuesTest, ChaosMonkeySafeLeaderTest, ShardRoutingTest, TestReplicationHandler, ZkSolrClientTest, TestRandomDVFaceting, ZkCLITest, ShardRoutingCustomTest, TestFaceting, TermVectorComponentDistributedTest, TestRealTimeGet, TestStressVersions, TestRangeQuery, TestCoreContainer, TestSolr4Spatial, StatsComponentTest, SolrCmdDistributorTest, PeerSyncTest, BadIndexSchemaTest, TestSort, TestLazyCores, OverseerCollectionProcessorTest, CurrencyFieldXmlFileTest, SuggesterFSTTest, SuggesterTest, SuggesterWFSTTest, PolyFieldTest, TestPseudoReturnFields, FieldMutatingUpdateProcessorTest, DefaultValueUpdateProcessorTest, StatelessScriptUpdateProcessorFactoryTest, DebugComponentTest, TestQueryUtils, TestReversedWildcardFilterFactory, DocumentAnalysisRequestHandlerTest, TestOmitPositions, TermsComponentTest, TestIndexingPerformance, TestArbitraryIndexDir, IndexSchemaRuntimeFieldTest, SolrPluginUtilsTest, TestCollationField, JsonLoaderTest, PingRequestHandlerTest, TestLFUCache, UpdateParamsTest, TestSolrIndexConfig, BadComponentTest, MultiTermTest, NumericFieldsTest, TestFuzzyAnalyzedSuggestions, ExternalFileFieldSortTest, TestSolrCoreProperties, TestLuceneMatchVersion, TestPhraseSuggestions, TestCodecSupport, EchoParamsTest, TestDFRSimilarityFactory, TestLMDirichletSimilarityFactory, LegacyHTMLStripCharFilterTest, TestPluginEnable, TimeZoneUtilsTest, ResourceLoaderTest, TestFastLRUCache, TestSolrXMLSerializer, DOMUtilTest, TestUtils, TestRTGBase, ChaosMonkeyShardSplitTest]
[junit4:junit4] Completed on J0 in 169.89s, 1 test, 1 error <<< FAILURES!
[...truncated 10 lines...]
BUILD FAILED
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:380: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:360: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/build.xml:39: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/build.xml:181: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/solr/common-build.xml:437: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:1240: The following error occurred while executing this line:
/mnt/ssd/jenkins/workspace/Lucene-Solr-trunk-Linux/lucene/common-build.xml:884: There were test failures: 295 suites, 1231 tests, 1 error, 13 ignored (7 assumptions)
Total time: 40 minutes 49 seconds
Build step 'Invoke Ant' marked build as failure
Description set: Java: 32bit/jdk1.7.0_21 -server -XX:+UseSerialGC
Archiving artifacts
Recording test results
Email was triggered for: Failure
Sending email for trigger: Failure